airflow-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "dud (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (AIRFLOW-140) DagRun state not updated
Date Mon, 23 May 2016 09:50:13 GMT

    [ https://issues.apache.org/jira/browse/AIRFLOW-140?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15292963#comment-15292963
] 

dud edited comment on AIRFLOW-140 at 5/23/16 9:49 AM:
------------------------------------------------------

Hello.
I tried with the LocalExecutor as requested and I observed the same behaviour :
{code}
airflow=> SELECT * FROM task_instance WHERE dag_id = :dag_id ORDER BY execution_date ;
SELECT * FROM dag_run WHERE dag_id = :dag_id ; SELECT * FROM job ORDER BY start_date DESC
LIMIT 5;
 task_id   |       dag_id       |   execution_date    |         start_date         |     
    end_date          | duration  |  state  | try_number | hostname  | unixname | job_id |
pool |  queue  | priority_weight |    operator    | queued_dttm
----------+---------------+---------------------+----------------------------+----------------------------+-----------+---------+------------+-----------+----------+--------+------+---------+-----------------+----------------+-------------
 alt_sleep | dagrun_not_updated | 2016-05-20 07:45:00 | 2016-05-20 07:46:54.372843 |     
                      |           | running |          1 | localhost | airflow  |   3203 |
     | default |               1 | PythonOperator |
 alt_sleep | dagrun_not_updated | 2016-05-20 07:46:00 | 2016-05-20 07:47:19.317705 | 2016-05-20
07:47:29.453316 | 10.135611 | success |          1 | localhost | airflow  |   3204 |     
| default |               1 | PythonOperator |
 alt_sleep | dagrun_not_updated | 2016-05-20 07:47:00 | 2016-05-20 07:48:01.724885 |     
                      |           | running |          1 | localhost | airflow  |   3205 |
     | default |               1 | PythonOperator |
 alt_sleep | dagrun_not_updated | 2016-05-20 07:48:00 | 2016-05-20 07:49:12.031225 | 2016-05-20
07:49:22.083763 | 10.052538 | success |          1 | localhost | airflow  |   3206 |     
| default |               1 | PythonOperator |
(4 rows)

  id  |        dag_id      |   execution_date    |  state  |             run_id          
  | external_trigger | conf | end_date |         start_date    
------+---------------+---------------------+---------+--------------------------------+------------------+------+----------+----------------------------
 1485 | dagrun_not_updated | 2016-05-20 07:45:00 | running | scheduled__2016-05-20T07:45:00
| f                |      |          | 2016-05-20 07:46:38.30924
 1486 | dagrun_not_updated | 2016-05-20 07:46:00 | running | scheduled__2016-05-20T07:46:00
| f                |      |          | 2016-05-20 07:47:01.563541
 1487 | dagrun_not_updated | 2016-05-20 07:47:00 | running | scheduled__2016-05-20T07:47:00
| f                |      |          | 2016-05-20 07:48:00.016718
 1488 | dagrun_not_updated | 2016-05-20 07:48:00 | running | scheduled__2016-05-20T07:48:00
| f                |      |          | 2016-05-20 07:49:00.203204
(4 rows)

  id  | dag_id |  state  |   job_type   |         start_date         |          end_date 
        |      latest_heartbeat      | executor_class | hostname  | unixname 
------+--------+---------+--------------+----------------------------+----------------------------+----------------------------+----------------+-----------+----------
 3206 |        | success | LocalTaskJob | 2016-05-20 07:49:08.691714 | 2016-05-20 07:49:23.706144
| 2016-05-20 07:49:08.691725 | LocalExecutor  | localhost | airflow
 3205 |        | running | LocalTaskJob | 2016-05-20 07:48:01.155988 |                   
        | 2016-05-20 07:50:51.312164 | LocalExecutor  | localhost | airflow
 3204 |        | success | LocalTaskJob | 2016-05-20 07:47:16.153078 | 2016-05-20 07:47:31.168997
| 2016-05-20 07:47:16.153091 | LocalExecutor  | localhost | airflow
 3203 |        | running | LocalTaskJob | 2016-05-20 07:46:48.198379 |                   
        | 2016-05-20 07:50:53.42636  | LocalExecutor  | localhost | airflow
 3202 |        | running | SchedulerJob | 2016-05-20 07:45:31.43799  |                   
        | 2016-05-20 07:50:55.061958 | LocalExecutor  | localhost | airflow
{code}

Extract of database logs :
{code}
2016-05-20 07:47:31 UTC [24003-36] airflow@airflow LOG:  duration: 38.731 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:47:31.168997'::timestamp, latest_heartbeat='2016-05-20T07:47:16.153091'::timestamp
WHERE job.id = 3204
2016-05-20 07:49:23 UTC [24107-36] airflow@airflow LOG:  duration: 0.179 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:49:23.706144'::timestamp, latest_heartbeat='2016-05-20T07:49:08.691725'::timestamp
WHERE job.id = 3206
2016-05-20 07:52:03 UTC [23971-336] airflow@airflow LOG:  duration: 0.291 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:52:03.526927'::timestamp, latest_heartbeat='2016-05-20T07:46:48.198389'::timestamp
WHERE job.id = 3203
2016-05-20 07:53:06 UTC [24047-326] airflow@airflow LOG:  duration: 0.179 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:53:06.444879'::timestamp, latest_heartbeat='2016-05-20T07:48:01.155997'::timestamp
WHERE job.id = 3205
2016-05-20 07:53:10 UTC [24276-18] airflow@airflow LOG:  duration: 0.315 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1485
2016-05-20 07:53:10 UTC [24276-19] airflow@airflow LOG:  duration: 0.108 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1486
2016-05-20 07:53:10 UTC [24276-20] airflow@airflow LOG:  duration: 0.090 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1487
2016-05-20 07:53:10 UTC [24276-21] airflow@airflow LOG:  duration: 0.098 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1488
2016-05-20 07:53:40 UTC [24307-36] airflow@airflow LOG:  duration: 0.177 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:53:40.881165'::timestamp, latest_heartbeat='2016-05-20T07:53:25.864395'::timestamp
WHERE job.id = 3208
{code}

Extract of Airflow logs 
{code}
May 20 07:47:29 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:29,947] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:39,950] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:44 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:44,955] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:49 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:49,963] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:55 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:54,967] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:00 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:00,102] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:09 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:09,996] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:19 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:19,995] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:24 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:24,996] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:30 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:30,001] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:35 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:35,008] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:40,006] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:45 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:45,015] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:50 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:50,079] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:00 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:00,273] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:05 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:05,682] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:16 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:16,606] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:25 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:25,045] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:25 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:25,046] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:30 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:30,080] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:30 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:30,081] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:40,511] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:40,511] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:50 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:50,072] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:50 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:50,073] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:55 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:55,074] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:55 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:55,074] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
{code}

For the record I'm getting the same issue with the CeleryExecutor as well.
dud


was (Author: dud):
Hello.
I tried with the LocalExecutor as requested and I observed the same behaviour :
{code}
airflow=> SELECT * FROM task_instance WHERE dag_id = :dag_id ORDER BY execution_date ;
SELECT * FROM dag_run WHERE dag_id = :dag_id ; SELECT * FROM job ORDER BY start_date DESC
LIMIT 5;
 task_id   |       dag_id       |   execution_date    |         start_date         |     
    end_date          | duration  |  state  | try_number | hostname  | unixname | job_id |
pool |  queue  | priority_weight |    operator    | queued_dttm
----------+---------------+---------------------+----------------------------+----------------------------+-----------+---------+------------+-----------+----------+--------+------+---------+-----------------+----------------+-------------
 alt_sleep | dagrun_not_updated | 2016-05-20 07:45:00 | 2016-05-20 07:46:54.372843 |     
                      |           | running |          1 | localhost | airflow  |   3203 |
     | default |               1 | PythonOperator |
 alt_sleep | dagrun_not_updated | 2016-05-20 07:46:00 | 2016-05-20 07:47:19.317705 | 2016-05-20
07:47:29.453316 | 10.135611 | success |          1 | localhost | airflow  |   3204 |     
| default |               1 | PythonOperator |
 alt_sleep | dagrun_not_updated | 2016-05-20 07:47:00 | 2016-05-20 07:48:01.724885 |     
                      |           | running |          1 | localhost | airflow  |   3205 |
     | default |               1 | PythonOperator |
 alt_sleep | dagrun_not_updated | 2016-05-20 07:48:00 | 2016-05-20 07:49:12.031225 | 2016-05-20
07:49:22.083763 | 10.052538 | success |          1 | localhost | airflow  |   3206 |     
| default |               1 | PythonOperator |
(4 rows)

  id  |        dag_id      |   execution_date    |  state  |             run_id          
  | external_trigger | conf | end_date |         start_date    
------+---------------+---------------------+---------+--------------------------------+------------------+------+----------+----------------------------
 1485 | dagrun_not_updated | 2016-05-20 07:45:00 | running | scheduled__2016-05-20T07:45:00
| f                |      |          | 2016-05-20 07:46:38.30924
 1486 | dagrun_not_updated | 2016-05-20 07:46:00 | running | scheduled__2016-05-20T07:46:00
| f                |      |          | 2016-05-20 07:47:01.563541
 1487 | dagrun_not_updated | 2016-05-20 07:47:00 | running | scheduled__2016-05-20T07:47:00
| f                |      |          | 2016-05-20 07:48:00.016718
 1488 | dagrun_not_updated | 2016-05-20 07:48:00 | running | scheduled__2016-05-20T07:48:00
| f                |      |          | 2016-05-20 07:49:00.203204
(4 rows)

  id  | dag_id |  state  |   job_type   |         start_date         |          end_date 
        |      latest_heartbeat      | executor_class | hostname  | unixname 
------+--------+---------+--------------+----------------------------+----------------------------+----------------------------+----------------+-----------+----------
 3206 |        | success | LocalTaskJob | 2016-05-20 07:49:08.691714 | 2016-05-20 07:49:23.706144
| 2016-05-20 07:49:08.691725 | LocalExecutor  | localhost | airflow
 3205 |        | running | LocalTaskJob | 2016-05-20 07:48:01.155988 |                   
        | 2016-05-20 07:50:51.312164 | LocalExecutor  | localhost | airflow
 3204 |        | success | LocalTaskJob | 2016-05-20 07:47:16.153078 | 2016-05-20 07:47:31.168997
| 2016-05-20 07:47:16.153091 | LocalExecutor  | localhost | airflow
 3203 |        | running | LocalTaskJob | 2016-05-20 07:46:48.198379 |                   
        | 2016-05-20 07:50:53.42636  | LocalExecutor  | localhost | airflow
 3202 |        | running | SchedulerJob | 2016-05-20 07:45:31.43799  |                   
        | 2016-05-20 07:50:55.061958 | LocalExecutor  | localhost | airflow
{code}

Extract of database logs :
{code}
2016-05-20 07:47:31 UTC [24003-36] airflow@airflow LOG:  duration: 38.731 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:47:31.168997'::timestamp, latest_heartbeat='2016-05-20T07:47:16.153091'::timestamp
WHERE job.id = 3204
2016-05-20 07:49:23 UTC [24107-36] airflow@airflow LOG:  duration: 0.179 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:49:23.706144'::timestamp, latest_heartbeat='2016-05-20T07:49:08.691725'::timestamp
WHERE job.id = 3206
2016-05-20 07:52:03 UTC [23971-336] airflow@airflow LOG:  duration: 0.291 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:52:03.526927'::timestamp, latest_heartbeat='2016-05-20T07:46:48.198389'::timestamp
WHERE job.id = 3203
2016-05-20 07:53:06 UTC [24047-326] airflow@airflow LOG:  duration: 0.179 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:53:06.444879'::timestamp, latest_heartbeat='2016-05-20T07:48:01.155997'::timestamp
WHERE job.id = 3205
2016-05-20 07:53:10 UTC [24276-18] airflow@airflow LOG:  duration: 0.315 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1485
2016-05-20 07:53:10 UTC [24276-19] airflow@airflow LOG:  duration: 0.108 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1486
2016-05-20 07:53:10 UTC [24276-20] airflow@airflow LOG:  duration: 0.090 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1487
2016-05-20 07:53:10 UTC [24276-21] airflow@airflow LOG:  duration: 0.098 ms  statement: UPDATE
dag_run SET state='success' WHERE dag_run.id = 1488
2016-05-20 07:53:40 UTC [24307-36] airflow@airflow LOG:  duration: 0.177 ms  statement: UPDATE
job SET state='success', end_date='2016-05-20T07:53:40.881165'::timestamp, latest_heartbeat='2016-05-20T07:53:25.864395'::timestamp
WHERE job.id = 3208
{code}

Extract of Airflow logs 
{code}
May 20 07:47:29 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:29,947] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:39,950] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:44 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:44,955] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:49 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:49,963] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:47:55 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:47:54,967] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:00 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:00,102] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:09 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:09,996] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:19 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:19,995] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:24 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:24,996] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:30 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:30,001] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:35 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:35,008] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:40,006] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:45 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:45,015] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:48:50 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:48:50,079] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:00 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:00,273] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:05 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:05,682] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:16 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:16,606] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:25 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:25,045] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:25 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:25,046] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:30 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:30,080] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:30 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:30,081] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:40,511] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:40 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:40,511] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:50 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:50,072] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:50 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:50,073] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
May 20 07:49:55 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:55,074] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:46:00: scheduled__2016-05-20T07:46:00,
externally triggered: False> successful
May 20 07:49:55 airflow-ec2 airflow-scheduler[23873]: [2016-05-20 07:49:55,074] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-20 07:48:00: scheduled__2016-05-20T07:48:00,
externally triggered: False> successful
{code}

For the record I'm getting the same issue with the SequentialExecutor and the CeleryExecutor
as well.
dud

> DagRun state not updated
> ------------------------
>
>                 Key: AIRFLOW-140
>                 URL: https://issues.apache.org/jira/browse/AIRFLOW-140
>             Project: Apache Airflow
>          Issue Type: Bug
>          Components: scheduler
>         Environment: Airflow latest Git version
>            Reporter: dud
>            Priority: Minor
>
> Hello
> I've noticed a strange behaviour : when launching a DAG whose task execution duration
is alternatingly slower and longer, DagRun state is only updated if all previous DagRuns have
ended.
> Here is DAG that can trigger this behaviour :
> {code}
> from airflow import DAG
> from airflow.operators import *
> from datetime import datetime, timedelta
> from time import sleep
> default_args = {
>     'owner': 'airflow',
>     'depends_on_past': False,
>     'start_date': datetime(2016, 5, 19, 10, 15),
>     'end_date': datetime(2016, 5, 19, 10, 20),
> }
> dag = DAG('dagrun_not_updated', default_args=default_args, schedule_interval=timedelta(minutes=1))
> def alternating_sleep(**kwargs):
>     minute = kwargs['execution_date'].strftime("%M")
>     is_odd = int(minute) % 2
>     if is_odd:
>         sleep(300)
>     else:
>         sleep(10)
>     return True
> PythonOperator(
>     task_id='alt_sleep',
>     python_callable=alternating_sleep,
>     provide_context=True,
>     dag=dag)
> {code}
> When this operator is executed, being run at an even minute makes the TI runs faster
than an odd one.
> I'm observing the following behaviour :
> - after some time, the second DagRun is still i running state despites it has ended for
a while :
> {code}
> airflow=> SELECT * FROM task_instance WHERE dag_id = :dag_id ORDER BY execution_date
;  SELECT * FROM dag_run WHERE dag_id = :dag_id ;
>   task_id  |       dag_id       |   execution_date    |         start_date         |
         end_date          | duration  |  state  | try_number | hostname  | unixname | job_id
| pool |  queue  | priority_weight |    operator    | queued_dttm
> ----------+---------------+---------------------+----------------------------+----------------------------+-----------+---------+------------+-----------+----------+--------+------+---------+-----------------+----------------+-------------
>  alt_sleep | dagrun_not_updated | 2016-05-19 10:15:00 | 2016-05-19 10:17:19.039565 |
                           |           | running |          1 | localhost | airflow  |   3196
|      | default |               1 | PythonOperator |
>  alt_sleep | dagrun_not_updated | 2016-05-19 10:16:00 | 2016-05-19 10:17:23.698928 |
2016-05-19 10:17:33.823066 | 10.124138 | success |          1 | localhost | airflow  |   3197
|      | default |               1 | PythonOperator |
>  alt_sleep | dagrun_not_updated | 2016-05-19 10:17:00 | 2016-05-19 10:18:03.025546 |
                           |           | running |          1 | localhost | airflow  |   3198
|      | default |               1 | PythonOperator |
> (3 rows)
>   id  |       dag_id       |   execution_date    |  state  |             run_id     
       | external_trigger | conf | end_date |         start_date    
> ------+---------------+---------------------+---------+--------------------------------+------------------+------+----------+----------------------------
>  1479 | dagrun_not_updated | 2016-05-19 10:15:00 | running | scheduled__2016-05-19T10:15:00
| f                |      |          | 2016-05-19 10:17:06.563842
>  1480 | dagrun_not_updated | 2016-05-19 10:16:00 | running | scheduled__2016-05-19T10:16:00
| f                |      |          | 2016-05-19 10:17:12.188781
>  1481 | dagrun_not_updated | 2016-05-19 10:17:00 | running | scheduled__2016-05-19T10:17:00
| f                |      |          | 2016-05-19 10:18:01.550625
> (3 rows)
> {code}
> - afer some time, all reportedly still running DagRuns are being marked as successful
at the same time :
> {code}
> 2016-05-19 10:23:11 UTC [12073-18] airflow@airflow LOG:  duration: 0.168 ms  statement:
UPDATE dag_run SET state='success' WHERE dag_run.id = 1479
> 2016-05-19 10:23:11 UTC [12073-19] airflow@airflow LOG:  duration: 0.106 ms  statement:
UPDATE dag_run SET state='success' WHERE dag_run.id = 1480
> 2016-05-19 10:23:11 UTC [12073-20] airflow@airflow LOG:  duration: 0.083 ms  statement:
UPDATE dag_run SET state='success' WHERE dag_run.id = 1481
> 2016-05-19 10:23:11 UTC [12073-21] airflow@airflow LOG:  duration: 0.081 ms  statement:
UPDATE dag_run SET state='success' WHERE dag_run.id = 1482
> {code}
> So it waited till the 4th DagRun ended to update the dag_run table.
> I've looked at the code I'm not sure whether the issue lies in Airflow as the scheduler
properly runs the code that updates the state to sucess :
> {code}
> May 19 10:17:36 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:17:36,542] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:17:41 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:17:41,666] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:17:51 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:17:51,571] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:17:56 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:17:56,578] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:01 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:01,591] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:06 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:06,735] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:16 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:16,599] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:21 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:21,623] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:31 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:31,651] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:41 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:41,611] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:46 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:46,625] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:18:56 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:18:56,619] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:01 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:01,640] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:07 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:07,355] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:16 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:16,633] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:21 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:21,710] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:21 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:21,711] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:19:31 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:31,646] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:31 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:31,647] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:19:36 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:36,650] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:36 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:36,651] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:19:41 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:41,656] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:41 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:41,657] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:19:51 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:51,659] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:51 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:51,659] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:19:56 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:56,664] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:19:56 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:19:56,664] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:20:01 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:01,670] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:20:01 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:01,671] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:20:06 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:06,669] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:20:06 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:06,674] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:20:11 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:11,739] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:20:11 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:11,739] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:20:21 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:21,726] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:20:21 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:21,727] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:20:31 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:31,699] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:20:31 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:31,699] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> May 19 10:20:36 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:36,700] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:16:00: scheduled__2016-05-19T10:16:00,
externally triggered: False> successful
> May 19 10:20:36 airflow-ec2 airflow-scheduler[11543]: [2016-05-19 10:20:36,700] {models.py:2725}
INFO - Marking run <DagRun dagrun_not_updated @ 2016-05-19 10:18:00: scheduled__2016-05-19T10:18:00,
externally triggered: False> successful
> {code}
> I've also verified that the scheduler runs session.commit(). But for some reason this
doesn't trigger any database sync.
> Please note that I have the following parameters in my configuration that may be related
with the behaviour reported above :
> {code}
> parallelism = 4
> max_active_runs_per_dag = 4
> {code}
> dud



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)


Mime
View raw message