You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by GitBox <gi...@apache.org> on 2021/08/20 22:59:14 UTC
[GitHub] [airflow] ephraimbuddy commented on issue #16023: Running tasks marked as 'orphaned' and killed by scheduler
ephraimbuddy commented on issue #16023:
URL: https://github.com/apache/airflow/issues/16023#issuecomment-902998077
I ran the above provided DAG in LocalExecutor. Before I ran it, I did `airflow db reset`.
The first 16 tasks were successful but the next 17 tasks failed.
In scheduler log, I found the following:
```
[[34m2021-08-20 21:31:41,056[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-04 00:00:00+00:00: scheduled__2021-06-04T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:41,144[0m] {[34mscheduler_job.py:[0m1143} INFO[0m - Resetting orphaned tasks for active dag runs[0m
[[34m2021-08-20 21:31:41,152[0m] {[34mscheduler_job.py:[0m1165} INFO[0m - Marked 17 SchedulerJob instances as failed[0m
[[34m2021-08-20 21:31:41,177[0m] {[34mscheduler_job.py:[0m1209} INFO[0m - Reset the following 10 orphaned TaskInstances:
[01m<TaskInstance: long_running_pyoperator.sleep_well 2021-05-27 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-05-28 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-02 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-03 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-06 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-07 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-08 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-09 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-10 00:00:00+00:00 [running]>
<TaskInstance: long_running_pyoperator.sleep_well 2021-06-11 00:00:00+00:00 [running]>[22m[0m
[[34m2021-08-20 21:31:42,225[0m] {[34mdag.py:[0m2691} INFO[0m - Setting next_dagrun for [01mlong_running_pyoperator[22m to [01m2021-06-13T00:00:00+00:00[22m[0m
[[34m2021-08-20 21:31:42,307[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-06 00:00:00+00:00: scheduled__2021-06-06T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,324[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-07 00:00:00+00:00: scheduled__2021-06-07T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,333[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-08 00:00:00+00:00: scheduled__2021-06-08T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,352[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-09 00:00:00+00:00: scheduled__2021-06-09T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,374[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-10 00:00:00+00:00: scheduled__2021-06-10T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,383[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-11 00:00:00+00:00: scheduled__2021-06-11T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,400[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-05-27 00:00:00+00:00: scheduled__2021-05-27T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,422[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-05-28 00:00:00+00:00: scheduled__2021-05-28T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,429[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-05-29 00:00:00+00:00: scheduled__2021-05-29T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,443[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-05-30 00:00:00+00:00: scheduled__2021-05-30T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,463[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-05-31 00:00:00+00:00: scheduled__2021-05-31T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,484[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-01 00:00:00+00:00: scheduled__2021-06-01T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,503[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-02 00:00:00+00:00: scheduled__2021-06-02T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,511[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-03 00:00:00+00:00: scheduled__2021-06-03T00:00:00+00:00, externally triggered: False>[22m failed[0m
[[34m2021-08-20 21:31:42,519[0m] {[34mdagrun.py:[0m431} [31mERROR[0m - [31mMarking run [01m<DagRun long_running_pyoperator @ 2021-06-05 00:00:00+00:00: scheduled__2021-06-05T00:00:00+00:00, externally triggered: False>[22m failed[0m
```
In the scheduler tasks log for dag processing, I found the following:
```log
[2021-08-20 21:31:41,007] {processor.py:618} INFO - DAG(s) dict_keys(['long_running_pyoperator']) retrieved from /files/dags/long_running_pyoperator.py
[2021-08-20 21:31:41,051] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-04 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,082] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-05-29 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,097] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-05 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,116] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-05-30 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,139] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-01 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,164] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-05-31 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,189] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-05-28 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,201] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-03 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,212] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-05-27 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,224] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-02 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,236] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-09 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,246] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-11 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,255] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-07 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,265] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-08 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,276] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-10 00:00:00+00:00 [failed]> in state failed
[2021-08-20 21:31:41,285] {processor.py:575} INFO - Executed failure callback for <TaskInstance: long_running_pyoperator.sleep_well 2021-06-06 00:00:00+00:00 [failed]> in state failed
```
That could be as a result of the schedulerJob being marked as failed.
Then the task log:
```log
[2021-08-20, 21:31:46 UTC] {local_task_job.py:209} WARNING - State of this instance has been externally set to failed. Terminating instance.
[2021-08-20, 21:31:46 UTC] {process_utils.py:100} INFO - Sending Signals.SIGTERM to GPID 5738
[2021-08-20, 21:31:46 UTC] {taskinstance.py:1369} ERROR - Received SIGTERM. Terminating subprocesses.
[2021-08-20, 21:31:46 UTC] {process_utils.py:66} INFO - Process psutil.Process(pid=5738, status='terminated', exitcode=0, started='21:24:33') (5738) terminated with exit code 0
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org