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/05/21 22:44:37 UTC

[GitHub] [airflow] tazimmerman commented on issue #10790: Copy of [AIRFLOW-5071] JIRA: Thousands of Executor reports task instance X finished (success) although the task says its queued. Was the task killed externally?

tazimmerman commented on issue #10790:
URL: https://github.com/apache/airflow/issues/10790#issuecomment-846297186


   I'm able to reproduce this using the standard `TimeDeltaSensor` with Airflow 1.10.14 and the `DaskExecutor`. The logs aren't helpful (at least to someone unfamiliar with the source code), but it's clear that there is a "hiccup" where the occasional retry fails.
   
   For example, the attempts before & after this one are successful, and on this try, there is an ominous message:
   
   `Dependencies not met for <TaskInstance: daily.wait_until_9_30_pm 2021-05-20T05:00:00+00:00 [up_for_retry]>, dependency 'Not In Retry Period' FAILED: Task is not ready for retry yet but will be retried automatically. Current date is 2021-05-21T21:42:46.765694+00:00 and task will be retried at 2021-05-21T21:47:45.333113+00:00.`
   
   ```
   --------------------------------------------------------------------------------
   [2021-05-21 16:41:43,452] {taskinstance.py:881} INFO - Starting attempt 1 of 2
   [2021-05-21 16:41:43,452] {taskinstance.py:882} INFO -
   --------------------------------------------------------------------------------
   [2021-05-21 16:41:43,457] {taskinstance.py:901} INFO - Executing <Task(TimeDeltaSensor): wait_until_9_30_pm> on 2021-05-20T05:00:00+00:00
   [2021-05-21 16:41:43,461] {standard_task_runner.py:54} INFO - Started process 129312 to run task
   [2021-05-21 16:41:43,489] {standard_task_runner.py:77} INFO - Running: ['airflow', 'run', 'daily', 'wait_until_9_30_pm', '2021-05-20T05:00:00+00:00', '--job_id', '25008', '--pool', 'default_pool', '--raw', '-sd', 'DAGS_FOLDER//home/troy/miniconda3/envs/test/daily.py', '--cfg_path', '/tmp/tmp24yafd42']
   [2021-05-21 16:41:43,490] {standard_task_runner.py:78} INFO - Job 25008: Subtask wait_until_9_30_pm
   [2021-05-21 16:41:43,512] {logging_mixin.py:112} INFO - Running <TaskInstance: daily.wait_until_9_30_pm 2021-05-20T05:00:00+00:00 [running]> on localhost
   [2021-05-21 16:41:43,526] {time_delta_sensor.py:45} INFO - Checking if the time (2021-05-22 02:30:00+00:00) has come
   [2021-05-21 16:41:43,533] {taskinstance.py:1141} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
   [2021-05-21 16:41:48,428] {local_task_job.py:102} INFO - Task exited with return code 0
   [2021-05-21 16:42:46,765] {taskinstance.py:662} INFO - Dependencies not met for <TaskInstance: daily.wait_until_9_30_pm 2021-05-20T05:00:00+00:00 [up_for_retry]>, dependency 'Not In Retry Period' FAILED: Task is not ready for retry yet but will be retried automatically. Current date is 2021-05-21T21:42:46.765694+00:00 and task will be retried at 2021-05-21T21:47:45.333113+00:00.
   [2021-05-21 16:42:46,773] {local_task_job.py:90} INFO - Task is not able to be run
   [2021-05-21 16:47:53,044] {taskinstance.py:670} INFO - Dependencies all met for <TaskInstance: daily.wait_until_9_30_pm 2021-05-20T05:00:00+00:00 [queued]>
   [2021-05-21 16:47:53,059] {taskinstance.py:670} INFO - Dependencies all met for <TaskInstance: daily.wait_until_9_30_pm 2021-05-20T05:00:00+00:00 [queued]>
   [2021-05-21 16:47:53,059] {taskinstance.py:880} INFO -
   ```
   
   This happens every hour or so with `poke_interval=300`. I was hoping to use switch most of our sensors to `mode="reschedule"` but now I'm afraid it'll just mean even more alert emails.


-- 
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.

For queries about this service, please contact Infrastructure at:
users@infra.apache.org