You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "Henry Cohen (Jira)" <ji...@apache.org> on 2019/09/12 18:00:00 UTC
[jira] [Comment Edited] (AIRFLOW-5447) KubernetesExecutor hangs on
task queueing
[ https://issues.apache.org/jira/browse/AIRFLOW-5447?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16928788#comment-16928788 ]
Henry Cohen edited comment on AIRFLOW-5447 at 9/12/19 5:59 PM:
---------------------------------------------------------------
`[2019-09-12 17:56:03,034] {{kubernetes_executor.py:698}} INFO - TaskInstance: <TaskInstance: tutorial.print_date 2019-09-10 00:00:00+00:00 [queued]> found in queued state but was not launched, rescheduling
[2019-09-12 17:56:03,043] {{scheduler_job.py:1376}} INFO - Resetting orphaned tasks for active dag runs
[2019-09-12 17:56:03,085] {{base_job.py:308}} INFO - Reset the following 30 TaskInstances:
<TaskInstance: latest_only.latest_only 2019-09-10 04:00:00+00:00 [None]>
<TaskInstance: example_branch_operator.run_this_first 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: tutorial.print_date 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_2 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_1 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_2 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_1 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_True 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_False 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_branch_dop_operator_v3.condition 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_http_operator.http_sensor_check 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_passing_params_via_test_command.run_this 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_trigger_controller_dag.test_trigger_dagrun 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_1 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_1 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_True 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_False 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.runme_2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.runme_1 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.runme_0 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.also_run_this 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_xcom.push_by_returning 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_xcom.push 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_branch_operator.run_this_first 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: latest_only.latest_only 2019-09-10 00:00:00+00:00 [None]>
[2019-09-12 17:56:03,092] {{dag_processing.py:545}} INFO - Launched DagFileProcessorManager with pid: 35
[2019-09-12 17:56:03,093] {{scheduler_job.py:1390}} DEBUG - Starting Loop...
[2019-09-12 17:56:03,093] {{scheduler_job.py:1401}} DEBUG - Harvesting DAG parsing results
[2019-09-12 17:56:03,093] {{scheduler_job.py:1403}} DEBUG - Harvested 0 SimpleDAGs
[2019-09-12 17:56:03,093] {{scheduler_job.py:1438}} DEBUG - Heartbeating the executor
[2019-09-12 17:56:03,093] {{base_executor.py:124}} DEBUG - 0 running task instances
[2019-09-12 17:56:03,094] {{base_executor.py:125}} DEBUG - 0 in queue
[2019-09-12 17:56:03,094] {{base_executor.py:126}} DEBUG - 96 open slots
[2019-09-12 17:56:03,094] {{base_executor.py:135}} DEBUG - Calling the <class 'airflow.contrib.executors.kubernetes_executor.KubernetesExecutor'> sync method
[2019-09-12 17:56:03,100] {{scheduler_job.py:1459}} DEBUG - Ran scheduling loop in 0.01 seconds
[2019-09-12 17:56:03,101] {{scheduler_job.py:1462}} DEBUG - Sleeping for 1.00 seconds
[2019-09-12 17:56:03,107] {{settings.py:54}} INFO - Configured default timezone <Timezone [America/New_York]>
[2019-09-12 17:56:03,109] {{settings.py:327}} DEBUG - Failed to import airflow_local_settings.
Traceback (most recent call last):
File "/usr/local/lib/python3.7/site-packages/airflow/settings.py", line 315, in import_local_settings
import airflow_local_settings
ModuleNotFoundError: No module named 'airflow_local_settings'
[2019-09-12 17:56:03,111] {{logging_config.py:47}} INFO - Successfully imported user-defined logging config from log_config.LOGGING_CONFIG
[2019-09-12 17:56:03,120] {{settings.py:170}} DEBUG - Setting up DB connection pool (PID 35)
[2019-09-12 17:56:03,121] {{settings.py:213}} INFO - settings.configure_orm(): Using pool settings. pool_size=5, max_overflow=10, pool_recycle=1800, pid=35
[2019-09-12 17:56:03,289] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 45)
[2019-09-12 17:56:03,356] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 41)
[2019-09-12 17:56:04,101] {{scheduler_job.py:1474}} DEBUG - Sleeping for 0.99 seconds to prevent excessive logging
[2019-09-12 17:56:04,126] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor0-Process, stopped)>
[2019-09-12 17:56:04,127] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor1-Process, stopped)>
[2019-09-12 17:56:04,162] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 55)
[2019-09-12 17:56:04,223] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 58)
[2019-09-12 17:56:05,095] {{scheduler_job.py:1390}} DEBUG - Starting Loop...
[2019-09-12 17:56:05,095] {{scheduler_job.py:1401}} DEBUG - Harvesting DAG parsing results
[2019-09-12 17:56:05,097] {{dag_processing.py:637}} DEBUG - Received message of type DagParsingStat
[2019-09-12 17:56:05,098] {{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,098] {{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,099] {{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,099] {{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,100] {{dag_processing.py:637}} DEBUG - Received message of type DagParsingStat
[2019-09-12 17:56:05,101] {{dag_processing.py:637}} DEBUG - Received message of type DagParsingStat
[2019-09-12 17:56:05,101] {{scheduler_job.py:1403}} DEBUG - Harvested 4 SimpleDAGs
[2019-09-12 17:56:05,128] {{scheduler_job.py:921}} INFO - 5 tasks up for execution:
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 04:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 04:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [scheduled]>
[2019-09-12 17:56:05,138] {{scheduler_job.py:953}} INFO - Figuring out tasks to run in Pool(name=default_pool) with 128 open slots and 5 task instances ready to be queued
[2019-09-12 17:56:05,139] {{scheduler_job.py:981}} INFO - DAG example_subdag_operator has 0/48 running and queued tasks
[2019-09-12 17:56:05,139] {{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 0/48 running and queued tasks
[2019-09-12 17:56:05,139] {{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 1/48 running and queued tasks
[2019-09-12 17:56:05,139] {{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 2/48 running and queued tasks
[2019-09-12 17:56:05,139] {{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 3/48 running and queued tasks
[2019-09-12 17:56:05,139] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor2-Process, stopped)>
[2019-09-12 17:56:05,140] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor3-Process, stopped)>
[2019-09-12 17:56:05,157] {{scheduler_job.py:1031}} INFO - Setting the following tasks to queued state:
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 04:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 04:00:00+00:00 [scheduled]>
[2019-09-12 17:56:05,182] {{scheduler_job.py:1107}} INFO - Setting the following 5 tasks to queued state:
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [queued]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [queued]>
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [queued]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 04:00:00+00:00 [queued]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 04:00:00+00:00 [queued]>
[2019-09-12 17:56:05,183] {{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'latest_only', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 4 and queue default
[2019-09-12 17:56:05,183] {{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'latest_only', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,183] {{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'task2', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 3 and queue default
[2019-09-12 17:56:05,183] {{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'task2', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,184] {{scheduler_job.py:1143}} INFO - Sending ('example_subdag_operator', 'start', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 5 and queue default
[2019-09-12 17:56:05,184] {{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'example_subdag_operator', 'start', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_subdag_operator.py']
[2019-09-12 17:56:05,184] {{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'latest_only', datetime.datetime(2019, 9, 10, 4, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 4 and queue default
[2019-09-12 17:56:05,184] {{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'latest_only', '2019-09-10T04:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,185] {{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'task2', datetime.datetime(2019, 9, 10, 4, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 3 and queue default
[2019-09-12 17:56:05,185] {{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'task2', '2019-09-10T04:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,185] {{scheduler_job.py:1438}} DEBUG - Heartbeating the executor
[2019-09-12 17:56:05,185] {{base_executor.py:124}} DEBUG - 0 running task instances
[2019-09-12 17:56:05,186] {{base_executor.py:125}} DEBUG - 5 in queue
[2019-09-12 17:56:05,186] {{base_executor.py:126}} DEBUG - 96 open slots
[2019-09-12 17:56:05,186] {{kubernetes_executor.py:764}} INFO - Add task ('example_subdag_operator', 'start', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) with command ['airflow', 'run', 'example_subdag_operator', 'start', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_subdag_operator.py'] with executor_config {}
[2019-09-12 17:56:05,193] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 72)
[2019-09-12 17:56:05,315] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 69)
[2019-09-12 17:56:06,153] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor4-Process, stopped)>
[2019-09-12 17:56:06,154] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor5-Process, stopped)>
[2019-09-12 17:56:06,290] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 83)
[2019-09-12 17:56:06,322] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 86)
[2019-09-12 17:56:07,171] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor6-Process, stopped)>
[2019-09-12 17:56:07,171] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor7-Process, stopped)>
[2019-09-12 17:56:07,248] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 97)
[2019-09-12 17:56:07,415] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 100)
[2019-09-12 17:56:08,188] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor8-Process, stopped)>
[2019-09-12 17:56:08,189] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor9-Process, stopped)>
[2019-09-12 17:56:08,247] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 111)
[2019-09-12 17:56:08,379] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 114)
[2019-09-12 17:56:09,205] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor10-Process, stopped)>
[2019-09-12 17:56:09,206] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor11-Process, stopped)>
[2019-09-12 17:56:09,323] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 125)
[2019-09-12 17:56:09,444] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 127)
[2019-09-12 17:56:10,223] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor12-Process, stopped)>
[2019-09-12 17:56:10,223] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor13-Process, stopped)>
[2019-09-12 17:56:10,299] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 139)
[2019-09-12 17:56:10,325] {{settings.py:238}} DEBUG - Disposing DB connection pool (PID 142)
[2019-09-12 17:56:11,237] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor14-Process, stopped)>
[2019-09-12 17:56:11,238] {{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor15-Process, stopped)>`
was (Author: hpcohen):
```[2019-09-12 17:56:03,034] \{{kubernetes_executor.py:698}} INFO - TaskInstance: <TaskInstance: tutorial.print_date 2019-09-10 00:00:00+00:00 [queued]> found in queued state but was not launched, rescheduling
[2019-09-12 17:56:03,043] \{{scheduler_job.py:1376}} INFO - Resetting orphaned tasks for active dag runs
[2019-09-12 17:56:03,085] \{{base_job.py:308}} INFO - Reset the following 30 TaskInstances:
<TaskInstance: latest_only.latest_only 2019-09-10 04:00:00+00:00 [None]>
<TaskInstance: example_branch_operator.run_this_first 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: tutorial.print_date 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_2 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_1 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_2 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_1 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_True 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_False 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_branch_dop_operator_v3.condition 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_http_operator.http_sensor_check 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_passing_params_via_test_command.run_this 2019-09-11 00:00:00+00:00 [None]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_trigger_controller_dag.test_trigger_dagrun 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.skip_operator_1 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_skip_dag.always_true_1 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_True 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_short_circuit_operator.condition_is_False 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.runme_2 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.runme_1 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.runme_0 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_bash_operator.also_run_this 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_xcom.push_by_returning 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_xcom.push 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: example_branch_operator.run_this_first 2019-09-10 00:00:00+00:00 [None]>
<TaskInstance: latest_only.latest_only 2019-09-10 00:00:00+00:00 [None]>
[2019-09-12 17:56:03,092] \{{dag_processing.py:545}} INFO - Launched DagFileProcessorManager with pid: 35
[2019-09-12 17:56:03,093] \{{scheduler_job.py:1390}} DEBUG - Starting Loop...
[2019-09-12 17:56:03,093] \{{scheduler_job.py:1401}} DEBUG - Harvesting DAG parsing results
[2019-09-12 17:56:03,093] \{{scheduler_job.py:1403}} DEBUG - Harvested 0 SimpleDAGs
[2019-09-12 17:56:03,093] \{{scheduler_job.py:1438}} DEBUG - Heartbeating the executor
[2019-09-12 17:56:03,093] \{{base_executor.py:124}} DEBUG - 0 running task instances
[2019-09-12 17:56:03,094] \{{base_executor.py:125}} DEBUG - 0 in queue
[2019-09-12 17:56:03,094] \{{base_executor.py:126}} DEBUG - 96 open slots
[2019-09-12 17:56:03,094] \{{base_executor.py:135}} DEBUG - Calling the <class 'airflow.contrib.executors.kubernetes_executor.KubernetesExecutor'> sync method
[2019-09-12 17:56:03,100] \{{scheduler_job.py:1459}} DEBUG - Ran scheduling loop in 0.01 seconds
[2019-09-12 17:56:03,101] \{{scheduler_job.py:1462}} DEBUG - Sleeping for 1.00 seconds
[2019-09-12 17:56:03,107] \{{settings.py:54}} INFO - Configured default timezone <Timezone [America/New_York]>
[2019-09-12 17:56:03,109] \{{settings.py:327}} DEBUG - Failed to import airflow_local_settings.
Traceback (most recent call last):
File "/usr/local/lib/python3.7/site-packages/airflow/settings.py", line 315, in import_local_settings
import airflow_local_settings
ModuleNotFoundError: No module named 'airflow_local_settings'
[2019-09-12 17:56:03,111] \{{logging_config.py:47}} INFO - Successfully imported user-defined logging config from log_config.LOGGING_CONFIG
[2019-09-12 17:56:03,120] \{{settings.py:170}} DEBUG - Setting up DB connection pool (PID 35)
[2019-09-12 17:56:03,121] \{{settings.py:213}} INFO - settings.configure_orm(): Using pool settings. pool_size=5, max_overflow=10, pool_recycle=1800, pid=35
[2019-09-12 17:56:03,289] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 45)
[2019-09-12 17:56:03,356] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 41)
[2019-09-12 17:56:04,101] \{{scheduler_job.py:1474}} DEBUG - Sleeping for 0.99 seconds to prevent excessive logging
[2019-09-12 17:56:04,126] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor0-Process, stopped)>
[2019-09-12 17:56:04,127] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor1-Process, stopped)>
[2019-09-12 17:56:04,162] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 55)
[2019-09-12 17:56:04,223] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 58)
[2019-09-12 17:56:05,095] \{{scheduler_job.py:1390}} DEBUG - Starting Loop...
[2019-09-12 17:56:05,095] \{{scheduler_job.py:1401}} DEBUG - Harvesting DAG parsing results
[2019-09-12 17:56:05,097] \{{dag_processing.py:637}} DEBUG - Received message of type DagParsingStat
[2019-09-12 17:56:05,098] \{{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,098] \{{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,099] \{{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,099] \{{dag_processing.py:637}} DEBUG - Received message of type SimpleDag
[2019-09-12 17:56:05,100] \{{dag_processing.py:637}} DEBUG - Received message of type DagParsingStat
[2019-09-12 17:56:05,101] \{{dag_processing.py:637}} DEBUG - Received message of type DagParsingStat
[2019-09-12 17:56:05,101] \{{scheduler_job.py:1403}} DEBUG - Harvested 4 SimpleDAGs
[2019-09-12 17:56:05,128] \{{scheduler_job.py:921}} INFO - 5 tasks up for execution:
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 04:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 04:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [scheduled]>
[2019-09-12 17:56:05,138] \{{scheduler_job.py:953}} INFO - Figuring out tasks to run in Pool(name=default_pool) with 128 open slots and 5 task instances ready to be queued
[2019-09-12 17:56:05,139] \{{scheduler_job.py:981}} INFO - DAG example_subdag_operator has 0/48 running and queued tasks
[2019-09-12 17:56:05,139] \{{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 0/48 running and queued tasks
[2019-09-12 17:56:05,139] \{{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 1/48 running and queued tasks
[2019-09-12 17:56:05,139] \{{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 2/48 running and queued tasks
[2019-09-12 17:56:05,139] \{{scheduler_job.py:981}} INFO - DAG latest_only_with_trigger has 3/48 running and queued tasks
[2019-09-12 17:56:05,139] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor2-Process, stopped)>
[2019-09-12 17:56:05,140] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor3-Process, stopped)>
[2019-09-12 17:56:05,157] \{{scheduler_job.py:1031}} INFO - Setting the following tasks to queued state:
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 04:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [scheduled]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 04:00:00+00:00 [scheduled]>
[2019-09-12 17:56:05,182] \{{scheduler_job.py:1107}} INFO - Setting the following 5 tasks to queued state:
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 00:00:00+00:00 [queued]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 00:00:00+00:00 [queued]>
<TaskInstance: example_subdag_operator.start 2019-09-10 00:00:00+00:00 [queued]>
<TaskInstance: latest_only_with_trigger.latest_only 2019-09-10 04:00:00+00:00 [queued]>
<TaskInstance: latest_only_with_trigger.task2 2019-09-10 04:00:00+00:00 [queued]>
[2019-09-12 17:56:05,183] \{{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'latest_only', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 4 and queue default
[2019-09-12 17:56:05,183] \{{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'latest_only', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,183] \{{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'task2', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 3 and queue default
[2019-09-12 17:56:05,183] \{{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'task2', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,184] \{{scheduler_job.py:1143}} INFO - Sending ('example_subdag_operator', 'start', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 5 and queue default
[2019-09-12 17:56:05,184] \{{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'example_subdag_operator', 'start', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_subdag_operator.py']
[2019-09-12 17:56:05,184] \{{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'latest_only', datetime.datetime(2019, 9, 10, 4, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 4 and queue default
[2019-09-12 17:56:05,184] \{{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'latest_only', '2019-09-10T04:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,185] \{{scheduler_job.py:1143}} INFO - Sending ('latest_only_with_trigger', 'task2', datetime.datetime(2019, 9, 10, 4, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) to executor with priority 3 and queue default
[2019-09-12 17:56:05,185] \{{base_executor.py:59}} INFO - Adding to queue: ['airflow', 'run', 'latest_only_with_trigger', 'task2', '2019-09-10T04:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_latest_only_with_trigger.py']
[2019-09-12 17:56:05,185] \{{scheduler_job.py:1438}} DEBUG - Heartbeating the executor
[2019-09-12 17:56:05,185] \{{base_executor.py:124}} DEBUG - 0 running task instances
[2019-09-12 17:56:05,186] \{{base_executor.py:125}} DEBUG - 5 in queue
[2019-09-12 17:56:05,186] \{{base_executor.py:126}} DEBUG - 96 open slots
[2019-09-12 17:56:05,186] \{{kubernetes_executor.py:764}} INFO - Add task ('example_subdag_operator', 'start', datetime.datetime(2019, 9, 10, 0, 0, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1) with command ['airflow', 'run', 'example_subdag_operator', 'start', '2019-09-10T00:00:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/lib/python3.7/site-packages/airflow/example_dags/example_subdag_operator.py'] with executor_config {}
[2019-09-12 17:56:05,193] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 72)
[2019-09-12 17:56:05,315] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 69)
[2019-09-12 17:56:06,153] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor4-Process, stopped)>
[2019-09-12 17:56:06,154] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor5-Process, stopped)>
[2019-09-12 17:56:06,290] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 83)
[2019-09-12 17:56:06,322] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 86)
[2019-09-12 17:56:07,171] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor6-Process, stopped)>
[2019-09-12 17:56:07,171] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor7-Process, stopped)>
[2019-09-12 17:56:07,248] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 97)
[2019-09-12 17:56:07,415] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 100)
[2019-09-12 17:56:08,188] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor8-Process, stopped)>
[2019-09-12 17:56:08,189] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor9-Process, stopped)>
[2019-09-12 17:56:08,247] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 111)
[2019-09-12 17:56:08,379] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 114)
[2019-09-12 17:56:09,205] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor10-Process, stopped)>
[2019-09-12 17:56:09,206] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor11-Process, stopped)>
[2019-09-12 17:56:09,323] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 125)
[2019-09-12 17:56:09,444] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 127)
[2019-09-12 17:56:10,223] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor12-Process, stopped)>
[2019-09-12 17:56:10,223] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor13-Process, stopped)>
[2019-09-12 17:56:10,299] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 139)
[2019-09-12 17:56:10,325] \{{settings.py:238}} DEBUG - Disposing DB connection pool (PID 142)
[2019-09-12 17:56:11,237] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor14-Process, stopped)>
[2019-09-12 17:56:11,238] \{{scheduler_job.py:257}} DEBUG - Waiting for <Process(DagFileProcessor15-Process, stopped)>```
> KubernetesExecutor hangs on task queueing
> -----------------------------------------
>
> Key: AIRFLOW-5447
> URL: https://issues.apache.org/jira/browse/AIRFLOW-5447
> Project: Apache Airflow
> Issue Type: Bug
> Components: executor-kubernetes
> Affects Versions: 1.10.4, 1.10.5
> Environment: Kubernetes version v1.14.3, Airflow version 1.10.4-1.10.5
> Reporter: Henry Cohen
> Assignee: Daniel Imberman
> Priority: Blocker
>
> Starting in 1.10.4, and continuing in 1.10.5, when using the KubernetesExecutor, with the webserver and scheduler running in the kubernetes cluster, tasks are scheduled, but when added to the task queue, the executor process hangs indefinitely. Based on log messages, it appears to be stuck at this line https://github.com/apache/airflow/blob/v1-10-stable/airflow/contrib/executors/kubernetes_executor.py#L761
--
This message was sent by Atlassian Jira
(v8.3.2#803003)