Airflow 1.8 crash on python 3.4

[Jean Soula <so...@eisti.eu>]

Hi all,

Hope you're well.

I implement an airflow dag and I have an issue which I don't understand.

I work on a docker stack, with : 1 redis, 1 scheduler and 1 worker
container on the same instance. On scheduler and worker I install* python
3.4* (airflow 1.8) and distributed my task with *celery*. All my tasks are
python scripts that I execute with bash operator.

I would like to execute backfill sequentially for the main dag that's why I
implement a dag who call on each task a backfill for 1 day from the main
dag.

Here is the main dag:
[image: Images intégrées 1]

I don't understand why my backfill command failed randomly at the end of a
success task whereas in the log there are no problem on my python code.

Here is a stack trace from the *orchestrator* that I don't understand, if
someone understand this below, could you please help me.

Regards,
Jean

[2017-04-03 16:17:24,737] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:24,737] {bash_operator.py:94} INFO - [2017-04-03
16:17:24,737] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Insert_result_db 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0},
upstream_task_ids=['Compute_transformation']
[2017-04-03 16:17:24,850] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:24,850] {bash_operator.py:94} INFO - [2017-04-03
16:17:24,850] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Send_to_slack 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0}, upstream_task_ids=['Insert_result_db']
[2017-04-03 16:17:29,336] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:29,336] {bash_operator.py:94} INFO - [2017-04-03
16:17:29,336] {models.py:4024} INFO - Updating state for <DagRun
Preprocessing_Wifi_Data @ 2017-01-14 00:00:00:
backfill_2017-01-14T00:00:00, externally triggered: False> considering
9 task(s)
[2017-04-03 16:17:29,568] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:29,567] {bash_operator.py:94} INFO - [2017-04-03
16:17:29,567] {jobs.py:1978} INFO - [backfill progress] | finished run
0 of 1 | tasks waiting: 3 | succeeded: 6 | kicked_off: 0 | failed: 0 |
skipped: 0 | deadlocked: 0 | not ready: 3
[2017-04-03 16:17:29,681] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:29,680] {bash_operator.py:94} INFO - [2017-04-03
16:17:29,680] {models.py:1126} INFO - Dependencies all met for
<TaskInstance: Preprocessing_Wifi_Data.Compute_transformation
2017-01-14 00:00:00 [scheduled]>
[2017-04-03 16:17:29,730] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:29,730] {bash_operator.py:94} INFO - [2017-04-03
16:17:29,729] {base_executor.py:50} INFO - Adding to queue: airflow
run Preprocessing_Wifi_Data Compute_transformation 2017-01-14T00:00:00
--pickle 4 --local
[2017-04-03 16:17:29,841] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:29,841] {bash_operator.py:94} INFO - [2017-04-03
16:17:29,841] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Insert_result_db 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0},
upstream_task_ids=['Compute_transformation']
[2017-04-03 16:17:29,969] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:29,969] {bash_operator.py:94} INFO - [2017-04-03
16:17:29,968] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Send_to_slack 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0}, upstream_task_ids=['Insert_result_db']
[2017-04-03 16:17:34,339] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:34,339] {bash_operator.py:94} INFO - [2017-04-03
16:17:34,338] {celery_executor.py:78} INFO - [celery] queuing
('Preprocessing_Wifi_Data', 'Compute_transformation',
datetime.datetime(2017, 1, 14, 0, 0)) through celery, queue=default
[2017-04-03 16:17:34,342] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:34,342] {bash_operator.py:94} INFO - [2017-04-03
16:17:34,342] {jobs.py:1712} WARNING - ('Preprocessing_Wifi_Data',
'Compute_transaction', datetime.datetime(2017, 1, 14, 0, 0)) state
success not in started=dict_values([<TaskInstance:
Preprocessing_Wifi_Data.Compute_transformation 2017-01-14 00:00:00
[queued]>])
[2017-04-03 16:17:34,420] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:34,419] {bash_operator.py:94} INFO - [2017-04-03
16:17:34,419] {models.py:4024} INFO - Updating state for <DagRun
Preprocessing_Wifi_Data @ 2017-01-14 00:00:00:
backfill_2017-01-14T00:00:00, externally triggered: False> considering
9 task(s)
[2017-04-03 16:17:34,649] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:34,649] {bash_operator.py:94} INFO - [2017-04-03
16:17:34,649] {jobs.py:1978} INFO - [backfill progress] | finished run
0 of 1 | tasks waiting: 2 | succeeded: 6 | kicked_off: 1 | failed: 0 |
skipped: 0 | deadlocked: 0 | not ready: 2
[2017-04-03 16:17:34,726] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:34,726] {bash_operator.py:94} INFO - [2017-04-03
16:17:34,725] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Insert_result_db 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0},
upstream_task_ids=['Compute_transformation']
[2017-04-03 16:17:34,831] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:34,831] {bash_operator.py:94} INFO - [2017-04-03
16:17:34,831] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Send_to_slack 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0}, upstream_task_ids=['Insert_result_db']
[2017-04-03 16:17:37,483] {cli.py:391} INFO - Loading pickle id 3
[2017-04-03 16:17:38,150] {base_task_runner.py:112} INFO - Running:
['bash', '-c', 'airflow run ordonnanceur traj_2017-01-14
2017-01-12T00:00:00 --pickle 3 --job_id 62 --raw']
[2017-04-03 16:17:38,845] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:38,845] {__init__.py:57} INFO - Using executor
CeleryExecutor
[2017-04-03 16:17:39,133] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,133] {cli.py:391} INFO - Loading pickle id 3
[2017-04-03 16:17:39,399] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,399] {bash_operator.py:94} INFO - [2017-04-03
16:17:39,399] {models.py:4024} INFO - Updating state for <DagRun
Preprocessing_Wifi_Data @ 2017-01-14 00:00:00:
backfill_2017-01-14T00:00:00, externally triggered: False> considering
9 task(s)
[2017-04-03 16:17:39,624] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,623] {models.py:1120} INFO - Dependencies not met
for <TaskInstance: ordonnanceur.traj_2017-01-14 2017-01-12 00:00:00
[running]>, dependency 'Task Instance Not Already Running' FAILED:
Task is already running, it started on 2017-04-03 15:12:51.838323.
[2017-04-03 16:17:39,624] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,624] {models.py:1120} INFO - Dependencies not met
for <TaskInstance: ordonnanceur.traj_2017-01-14 2017-01-12 00:00:00
[running]>, dependency 'Task Instance State' FAILED: Task is in the
'running' state which is not a valid state for execution. The task
must be cleared in order to be run.
[2017-04-03 16:17:39,628] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,628] {bash_operator.py:94} INFO - [2017-04-03
16:17:39,628] {jobs.py:1978} INFO - [backfill progress] | finished run
0 of 1 | tasks waiting: 2 | succeeded: 6 | kicked_off: 1 | failed: 0 |
skipped: 0 | deadlocked: 0 | not ready: 2
[2017-04-03 16:17:39,707] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,707] {bash_operator.py:94} INFO - [2017-04-03
16:17:39,707] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Insert_result_db 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0},
upstream_task_ids=['Compute_transformation']
[2017-04-03 16:17:39,819] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:39,819] {bash_operator.py:94} INFO - [2017-04-03
16:17:39,819] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Send_to_slack 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0}, upstream_task_ids=['Insert_result_db']
[2017-04-03 16:17:43,182] {jobs.py:2148} WARNING - Recorded pid 79 is
not a descendant of the current pid 1452
[2017-04-03 16:17:44,439] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:44,438] {bash_operator.py:94} INFO - [2017-04-03
16:17:44,438] {models.py:4024} INFO - Updating state for <DagRun
Preprocessing_Wifi_Data @ 2017-01-14 00:00:00:
backfill_2017-01-14T00:00:00, externally triggered: False> considering
9 task(s)
[2017-04-03 16:17:44,670] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:44,670] {bash_operator.py:94} INFO - [2017-04-03
16:17:44,670] {jobs.py:1978} INFO - [backfill progress] | finished run
0 of 1 | tasks waiting: 2 | succeeded: 6 | kicked_off: 1 | failed: 0 |
skipped: 0 | deadlocked: 0 | not ready: 2
[2017-04-03 16:17:44,752] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:44,752] {bash_operator.py:94} INFO - [2017-04-03
16:17:44,751] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Insert_result_db 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0},
upstream_task_ids=['Compute_transformation']
[2017-04-03 16:17:44,864] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:44,864] {bash_operator.py:94} INFO - [2017-04-03
16:17:44,864] {models.py:1120} INFO - Dependencies not met for
<TaskInstance: Preprocessing_Wifi_Data.Send_to_slack 2017-01-14
00:00:00 [scheduled]>, dependency 'Trigger Rule' FAILED: Task's
trigger rule 'all_success' requires all upstream tasks to have
succeeded, but found 1 non-success(es).
upstream_tasks_state={'upstream_failed': 0, 'done': 0, 'successes': 0,
'failed': 0, 'skipped': 0}, upstream_task_ids=['Insert_result_db']
[2017-04-03 16:17:46,819] {jobs.py:2155} WARNING - State of this
instance has been externally set to up_for_retry. Taking the poison
pill. So long.
[2017-04-03 16:17:46,824] {helpers.py:220} WARNING - Terminating
descendant processes of
['/usr/local/bin/conda/envs/occi-airflow/bin/python
/usr/local/bin/conda/envs/occi-airflow/bin/airflow run ordonnanceur
traj_2017-01-14 2017-01-12T00:00:00 --pickle 3 --job_id 22 --raw']
PID: 79
[2017-04-03 16:17:46,825] {helpers.py:224} WARNING - Terminating
descendant process ['bash',
'/tmp/airflowtmpzt8b06cp/traj_2017-01-14tnsrsyv4'] PID: 85
[2017-04-03 16:17:46,893] {helpers.py:224} WARNING - Terminating
descendant process ['/usr/local/bin/conda/envs/occi-airflow/bin/python
/usr/local/bin/conda/envs/occi-airflow/bin/airflow backfill
Preprocessing_Wifi_Data -s 2017-01-14 -e 2017-01-14'] PID: 86
[2017-04-03 16:17:46,898] {helpers.py:231} WARNING - Waiting up to 5s
for processes to exit...
[2017-04-03 16:17:46,904] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:46,904] {bash_operator.py:97} INFO - Command exited
with return code -15
[2017-04-03 16:17:46,906] {helpers.py:234} WARNING - Done waiting
[2017-04-03 16:17:46,906] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:46,905] {models.py:1417} ERROR - Bash command failed
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
Traceback (most recent call last):
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/lib/python3.4/site-packages/airflow/models.py",
line 1374, in run
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
result = task_copy.execute(context=context)
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/lib/python3.4/site-packages/airflow/operators/bash_operator.py",
line 100, in execute
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
raise AirflowException("Bash command failed")
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
airflow.exceptions.AirflowException: Bash command failed
[2017-04-03 16:17:46,907] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:46,907] {models.py:1433} INFO - Marking task as
UP_FOR_RETRY
[2017-04-03 16:17:47,117] {base_task_runner.py:95} INFO - Subtask:
[2017-04-03 16:17:47,117] {models.py:1462} ERROR - Bash command failed
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
Traceback (most recent call last):
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/bin/airflow", line 28, in
<module>
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
args.func(args)
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/lib/python3.4/site-packages/airflow/bin/cli.py",
line 422, in run
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
pool=args.pool,
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/lib/python3.4/site-packages/airflow/utils/db.py",
line 53, in wrapper
[2017-04-03 16:17:47,120] {base_task_runner.py:95} INFO - Subtask:
result = func(*args, **kwargs)
[2017-04-03 16:17:47,121] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/lib/python3.4/site-packages/airflow/models.py",
line 1374, in run
[2017-04-03 16:17:47,121] {base_task_runner.py:95} INFO - Subtask:
result = task_copy.execute(context=context)
[2017-04-03 16:17:47,121] {base_task_runner.py:95} INFO - Subtask:
File "/usr/local/bin/conda/envs/occi-airflow/lib/python3.4/site-packages/airflow/operators/bash_operator.py",
line 100, in execute
[2017-04-03 16:17:47,121] {base_task_runner.py:95} INFO - Subtask:
raise AirflowException("Bash command failed")
[2017-04-03 16:17:47,121] {base_task_runner.py:95} INFO - Subtask:
airflow.exceptions.AirflowException: Bash command failed
[2017-04-03 16:17:51,807] {jobs.py:2083} INFO - Task exited with return code 1