[
https://issues.apache.org/jira/browse/AIRFLOW-5447?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16928788#comment-16928788
]
Henry Cohen commented on AIRFLOW-5447:
--------------------------------------
```[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)
