Task stuck as deferred

[Limess]

On Airflow version 2.3.3:

A task has become stuck in the deferred state.

Upon clearing the task, nothing happens.
Upon marking the task as a success/failure, the task is marked correctly, but after clearing it immediately goes back to deferred with the same retry number.

I'd expect the task to restart it's execution entirely when cleared.

I haven't raised a bug as I don't have any idea what to do to reproduce this - this hasn't happened to previous deferred tasks I've tried to clear

.

[potiuk]

Can you please take a look at all the logs (including triggerer log) and extracts the parts (and copy here) for the time when you are trying to clear the task? Especially if you see the logs showign something when you do and and referring to the task in question.

That would help enormously in analysing the problems.

[Limess]

Job logs:

[2022-08-10, 14:44:08 BST] {{taskinstance.py:1179}} INFO - Dependencies all met for <TaskInstance: offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs manual__2022-08-10T14:41:04+01:00 [queued]>
[2022-08-10, 14:44:08 BST] {{taskinstance.py:1179}} INFO - Dependencies all met for <TaskInstance: offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs manual__2022-08-10T14:41:04+01:00 [queued]>
[2022-08-10, 14:44:08 BST] {{taskinstance.py:1376}} INFO - 
--------------------------------------------------------------------------------
[2022-08-10, 14:44:08 BST] {{taskinstance.py:1377}} INFO - Starting attempt 1 of 2
[2022-08-10, 14:44:08 BST] {{taskinstance.py:1378}} INFO - 
--------------------------------------------------------------------------------
[2022-08-10, 14:44:08 BST] {{taskinstance.py:1397}} INFO - Executing <Task(OfflineProcessingSchedulerExecutionOperator): chunked_document_updater.execute_aws_batch_jobs> on 2022-08-10 13:41:04+00:00
[2022-08-10, 14:44:08 BST] {{standard_task_runner.py:52}} INFO - Started process 4814 to run task
[2022-08-10, 14:44:08 BST] {{standard_task_runner.py:79}} INFO - Running: ['airflow', 'tasks', 'run', 'offline-processing-articles-update-chunked-store-manual-trigger-v1', 'chunked_document_updater.execute_aws_batch_jobs', 'manual__2022-08-10T14:41:04+01:00', '--job-id', '3567501', '--raw', '--subdir', 'DAGS_FOLDER/signal_ai/data_platform/articles/offline_processing_articles_update_chunked_store.py', '--cfg-path', '/tmp/tmpecw8fty5', '--error-file', '/tmp/tmp_vk4raig']
[2022-08-10, 14:44:08 BST] {{standard_task_runner.py:80}} INFO - Job 3567501: Subtask chunked_document_updater.execute_aws_batch_jobs
[2022-08-10, 14:44:08 BST] {{task_command.py:371}} INFO - Running <TaskInstance: offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs manual__2022-08-10T14:41:04+01:00 [running]> on host 10.0.76.176
[2022-08-10, 14:44:08 BST] {{offline_processing_scheduler_execution_operator.py:201}} INFO - Execution lifecycle: "running", job statuses {'running': 1, 'scheduled': 1}
[2022-08-10, 14:44:08 BST] {{taskinstance.py:1479}} INFO - Pausing task as DEFERRED. dag_id=offline-processing-articles-update-chunked-store-manual-trigger-v1, task_id=chunked_document_updater.execute_aws_batch_jobs, execution_date=20220810T134104, start_date=20220810T134125
[2022-08-10, 14:44:08 BST] {{local_task_job.py:156}} INFO - Task exited with return code 0
[2022-08-10, 14:44:08 BST] {{local_task_job.py:273}} INFO - 0 downstream tasks scheduled from follow-on schedule check

Triggerer - no logs immediately after clearing, eventually:

2022-08-10T14:43:37 - [2022-08-10 13:43:37,613] {triggerer_job.py:358} INFO - Trigger <airflow.triggers.temporal.DateTimeTrigger moment=2022-08-10T13:44:05.829244+00:00> (ID 7056) starting
2022-08-10T14:43:51 - [2022-08-10 13:43:51,625] {triggerer_job.py:251} INFO - 1 triggers currently running

scheduler

2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,300] {scheduler_job.py:353} INFO - 1 tasks up for execution:
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 -    <TaskInstance: offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs manual__2022-08-10T14:41:04+01:00 [scheduled]>
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,300] {scheduler_job.py:418} INFO - DAG offline-processing-articles-update-chunked-store-manual-trigger-v1 has 0/64 running and queued tasks
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,300] {scheduler_job.py:504} INFO - Setting the following tasks to queued state:
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 -    <TaskInstance: offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs manual__2022-08-10T14:41:04+01:00 [scheduled]>
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,302] {scheduler_job.py:546} INFO - Sending TaskInstanceKey(dag_id='offline-processing-articles-update-chunked-store-manual-trigger-v1', task_id='chunked_document_updater.execute_aws_batch_jobs', run_id='manual__2022-08-10T14:41:04+01:00', try_number=1, map_index=-1) to executor with priority 1 and queue pipeline
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,302] {base_executor.py:91} INFO - Adding to queue: ['airflow', 'tasks', 'run', 'offline-processing-articles-update-chunked-store-manual-trigger-v1', 'chunked_document_updater.execute_aws_batch_jobs', 'manual__2022-08-10T14:41:04+01:00', '--local', '--subdir', 'DAGS_FOLDER/signal_ai/data_platform/articles/offline_processing_articles_update_chunked_store.py']
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,365] {scheduler_job.py:599} INFO - Executor reports execution of offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs run_id=manual__2022-08-10T14:41:04+01:00 exited with status queued for try_number 1
2022-08-10T14:42:48 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:48,371] {scheduler_job.py:632} INFO - Setting external_id for <TaskInstance: offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs manual__2022-08-10T14:41:04+01:00 [queued]> to dfa625c0-312d-486f-897a-928502104e4d
2022-08-10T14:42:49 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:49,659] {scheduler_job.py:599} INFO - Executor reports execution of offline-processing-articles-update-chunked-store-manual-trigger-v1.chunked_document_updater.execute_aws_batch_jobs run_id=manual__2022-08-10T14:41:04+01:00 exited with status success for try_number 1
2022-08-10T14:42:49 - default/application/363352bce525402ca5fe37da05050f72 - [2022-08-10 13:42:49,665] {scheduler_job.py:642} INFO - TaskInstance Finished: dag_id=offline-processing-articles-update-chunked-store-manual-trigger-v1, task_id=chunked_document_updater.execute_aws_batch_jobs, run_id=manual__2022-08-10T14:41:04+01:00, map_index=-1, run_start_date=2022-08-10 13:41:25.298802+00:00, run_end_date=None, run_duration=None, state=deferred, executor_state=success, try_number=1, max_tries=1, job_id=3567496, pool=default_pool, queue=pipeline, priority_weight=1, operator=OfflineProcessingSchedulerExecutionOperator, queued_dttm=2022-08-10 13:42:48.300628+00:00, queued_by_job_id=3557350, pid=4763

[potiuk]

@andrewgodwin -> does it ring a bell?

[Limess]

If it helps, the job logs are all from the method_name callback passed to self.defer, it never seems to be hitting execute on the task again after the first time, regardless of clearing.

[andrewgodwin]

The triggerer should drop the task as soon as it moves out of state DEFERRED, which naturally clearing should do, so I'm not quite sure what's going on here.

(not hitting execute is more normal - the task will still have the attribute which says "go here on next scheduling". Might want to clean that up in the clear method as well)

[Limess]

(not hitting execute is more normal - the task will still have the attribute which says "go here on next scheduling". Might want to clean that up in the clear method as well)

Useful to know, I'd assumed that clearing a deferred task would restart it totally.

[andrewgodwin]

Yes, it is meant to, but the nature of how Deferred was implemented means there's one additional field to clear that we may not have got cleared everywhere that restarts/retry/etc. are needed.

[potiuk]

Do we have a plan to change it @andrewgodwin ?

[andrewgodwin]

It should get looked at, definitely - I am travelling for conferences the next few weeks so I won't be able to.

[potiuk]

Ok. Created back #25859