Task runs second time after success

[Tonkonozhenko]

Apache Airflow version

2.2.4 (latest released)

What happened

Task runs a second time after a first successful run. We have some hourly dags and it happens once per few days.
In logs I see the suspicious line:

[2022-03-13, 09:10:59 UTC] {local_task_job.py:99} INFO - Task is not able to be run

Full log:

[2022-03-13, 09:10:59 UTC] {taskinstance.py:1027} INFO - Dependencies not met for <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [scheduled]>, dependency 'Task Instance State' FAILED: Task is in the 'scheduled' state.
[2022-03-13, 09:10:59 UTC] {local_task_job.py:99} INFO - Task is not able to be run

[2022-03-13, 09:11:16 UTC] {taskinstance.py:1037} INFO - Dependencies all met for <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [queued]>
[2022-03-13, 09:11:16 UTC] {taskinstance.py:1037} INFO - Dependencies all met for <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [queued]>
[2022-03-13, 09:11:16 UTC] {taskinstance.py:1243} INFO -
--------------------------------------------------------------------------------
[2022-03-13, 09:11:16 UTC] {taskinstance.py:1244} INFO - Starting attempt 1 of 3
[2022-03-13, 09:11:16 UTC] {taskinstance.py:1245} INFO -
--------------------------------------------------------------------------------
[2022-03-13, 09:11:16 UTC] {taskinstance.py:1264} INFO - Executing <Task(PythonOperator): task_id> on 2022-03-13 08:10:00+00:00
[2022-03-13, 09:11:16 UTC] {standard_task_runner.py:52} INFO - Started process 17071 to run task
[2022-03-13, 09:11:16 UTC] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'dag_id', 'task_id', 'scheduled__2022-03-13T08:10:00+00:00', '--job-id', '1331338', '--raw', '--subdir', 'DAGS_FOLDER/dag_id.py', '--cfg-path', '/tmp/tmp6jzxb7ar', '--error-file', '/tmp/tmpru98mcz9']
[2022-03-13, 09:11:16 UTC] {standard_task_runner.py:77} INFO - Job 1331338: Subtask task_id
[2022-03-13, 09:11:16 UTC] {logging_mixin.py:109} INFO - Running <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [running]> on host airflow-official-worker-7d594658ff-9d4nf
[2022-03-13, 09:11:17 UTC] {taskinstance.py:1429} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_EMAIL=...
AIRFLOW_CTX_DAG_OWNER=airflow
AIRFLOW_CTX_DAG_ID=dag_id
AIRFLOW_CTX_TASK_ID=task_id
AIRFLOW_CTX_EXECUTION_DATE=2022-03-13T08:10:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2022-03-13T08:10:00+00:00
[2022-03-13, 09:11:17 UTC] {python.py:175} INFO - Done. Returned value was: None
[2022-03-13, 09:11:17 UTC] {taskinstance.py:1272} INFO - Marking task as SUCCESS. dag_id=dag_id, task_id=task_id, execution_date=20220313T081000, start_date=20220313T091116, end_date=20220313T091117
[2022-03-13, 09:11:17 UTC] {local_task_job.py:154} INFO - Task exited with return code 0
[2022-03-13, 09:11:17 UTC] {local_task_job.py:264} INFO - 0 downstream tasks scheduled from follow-on schedule check

What you expected to happen

No response

How to reproduce

No response

Operating System

Debian 10, extended official airflow image

Versions of Apache Airflow Providers

No response

Deployment

Official Apache Airflow Helm Chart

Deployment details

No response

Anything else

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[potiuk]

Converted to discussion.

Those are just informational messages and they do not seem alarming.

It looks like it is pretty "normal" to happen occassionally and the log indicates that scheduler attempted to schedule a task (mistakenly) for which not all dependencies are met (this might be due to various race conditions) - but it correctly refused to start it in this case and apparenlty correctly run it at next scheduling loop when dependencies were already met.

If you have no problems resulting from that, then I'd say there is nothing to worry about.

[Tonkonozhenko]

@potiuk i have problems — task runs twice

[potiuk]

The logs show that the first time it is not run. Where do you see it run twice ? Did I miss it in the logs ?

[Tonkonozhenko]

Here is the second log:

*** Reading remote log from s3://.../airflow/dag_id/task_id/2022-03-13T08:10:00+00:00/2.log.
[2022-03-13, 09:12:32 UTC] {taskinstance.py:1037} INFO - Dependencies all met for <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [queued]>
[2022-03-13, 09:12:32 UTC] {taskinstance.py:1037} INFO - Dependencies all met for <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [queued]>
[2022-03-13, 09:12:32 UTC] {taskinstance.py:1243} INFO - 
--------------------------------------------------------------------------------
[2022-03-13, 09:12:32 UTC] {taskinstance.py:1244} INFO - Starting attempt 2 of 3
[2022-03-13, 09:12:32 UTC] {taskinstance.py:1245} INFO - 
--------------------------------------------------------------------------------
[2022-03-13, 09:12:32 UTC] {taskinstance.py:1264} INFO - Executing <Task(PythonOperator): task_id> on 2022-03-13 08:10:00+00:00
[2022-03-13, 09:12:32 UTC] {standard_task_runner.py:52} INFO - Started process 14811 to run task
[2022-03-13, 09:12:32 UTC] {standard_task_runner.py:76} INFO - Running: ['airflow', 'tasks', 'run', 'dag_id', 'task_id', 'scheduled__2022-03-13T08:10:00+00:00', '--job-id', '1331381', '--raw', '--subdir', 'DAGS_FOLDER/aws_transforms.py', '--cfg-path', '/tmp/tmp92i4e_p6', '--error-file', '/tmp/tmpk51vygac']
[2022-03-13, 09:12:32 UTC] {standard_task_runner.py:77} INFO - Job 1331381: Subtask task_id
[2022-03-13, 09:12:33 UTC] {logging_mixin.py:109} INFO - Running <TaskInstance: dag_id.task_id scheduled__2022-03-13T08:10:00+00:00 [running]> on host airflow-official-worker-7d594658ff-sphl7
[2022-03-13, 09:12:33 UTC] {taskinstance.py:1429} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_EMAIL=...
AIRFLOW_CTX_DAG_OWNER=airflow
AIRFLOW_CTX_DAG_ID=dag_id
AIRFLOW_CTX_TASK_ID=task_id
AIRFLOW_CTX_EXECUTION_DATE=2022-03-13T08:10:00+00:00
AIRFLOW_CTX_DAG_RUN_ID=scheduled__2022-03-13T08:10:00+00:00
[2022-03-13, 09:12:33 UTC] {python.py:175} INFO - Done. Returned value was: None
[2022-03-13, 09:12:33 UTC] {taskinstance.py:1272} INFO - Marking task as SUCCESS. dag_id=dag_id, task_id=task_id, execution_date=20220313T081000, start_date=20220313T091232, end_date=20220313T091233
[2022-03-13, 09:12:33 UTC] {local_task_job.py:154} INFO - Task exited with return code 0
[2022-03-13, 09:12:33 UTC] {local_task_job.py:264} INFO - 0 downstream tasks scheduled from follow-on schedule check

And here is audit log:

I guess it's related to keda autoscaling. We disabled it and observing

[Tonkonozhenko]

@potiuk also I just found a similar issue: #22068

[potiuk]

It looks like it's a different story. And same as there - more information and logs from both - scheduler(s) and database around the problem might be helpful.