Cloudwatch Integration: SIGTERM/SIGKILL Sent Following DAG Completion, Causing Errors in Worker Logs

[christmoore]

Apache Airflow version:
2.0.0

Environment:
Docker Stack
Celery Executor w/ Redis
3 Workers, Scheduler + Webserver
Cloudwatch remote config turned on

What happened:
Following execution of a DAG when using cloudwatch integration, the state of the Task Instance is being externally set, causing SIGTERM/SIGKILL signals to be sent. This causes error logs in Workers, which is a nuisance for alert monitoring

*** Reading remote log from Cloudwatch log_group: dev1-airflow-task log_stream: xxxx/task/2021-01-21T17_59_19.643994+00_00/1.log.
Dependencies all met for <TaskInstance: xxxx.task  2021-01-21T17:59:19.643994+00:00 [queued]>
Dependencies all met for <TaskInstance: xxxx.task  2021-01-21T17:59:19.643994+00:00 [queued]>
--------------------------------------------------------------------------------
Starting attempt 1 of 1
--------------------------------------------------------------------------------
Executing <Task(TaskVerificationOperator): task > on 2021-01-21T17:59:19.643994+00:00
Started process 654 to run task
Running <TaskInstance: xxxx.task  2021-01-21T17:59:19.643994+00:00 [running]> on host 88f99fbc97a8
Exporting the following env vars:
AIRFLOW_CTX_DAG_EMAIL=xxxxxxxx
AIRFLOW_CTX_DAG_OWNER=xxxxxxxx
AIRFLOW_CTX_DAG_ID=xxxxxxxx
AIRFLOW_CTX_TASK_ID=xxxxxx
AIRFLOW_CTX_EXECUTION_DATE=2021-01-21T17:59:19.643994+00:00
AIRFLOW_CTX_DAG_RUN_ID=85
Set new audit correlation_id xxxxxxxxxx-xxxxxx-xxxxxxxxx
Using connection to: id: xxxxx. Host: xxxxxxx, Port: 5432, Schema: xxxxxx, Login: xxxxxx, Password: XXXXXXXX, extra: None
Marking task as SUCCESS. dag_id=xxxxxx, task_id=xxxxxx, execution_date=20210121T175919, start_date=20210121T175936, end_date=20210121T175938
1 downstream tasks scheduled from follow-on schedule check

However following the completion of the DAG, the following is appended to the logs:

State of this instance has been externally set to success. Terminating instance.
Sending Signals.SIGTERM to GPID 654
process psutil.Process(pid=654, name='xxxxx', status='sleeping', started='17:59:36') did not respond to SIGTERM. Trying SIGKILL
Process psutil.Process(pid=654, name='xxxxx', status='terminated', exitcode=<Negsignal.SIGKILL: -9>, started='17:59:36') (654) terminated with exit code Negsignal.SIGKILL
Task exited with return code Negsignal.SIGKILL

This is a problem, because it causes the following to appear in Worker logs:

[2021-01-21 15:00:01,102: WARNING/ForkPoolWorker-8] Running <TaskInstance: xxxx.task 2021-01-21T14:00:00+00:00 [queued]> on host ip-172-31-3-210.ec2.internal
...
[2021-01-21 15:00:06,599: ERROR/ForkPoolWorker-8] Failed to execute task Task received SIGTERM signal.

What you expected to happen:
No errors to appear in Worker logs, if this SIGTERM/SIGKILL is intended

How to reproduce it:
Use Airflow w/ Celery Executor and Cloudwatch Remote Logging

Anything else we need to know:
Occurs every time, every task in DAG

[mtraynham]

One thing to note with this issue, I believe this is preventing workers from also consuming more work via a 60 second sleep at the end of every task. We noticed that there was a ~30-40 second delay between 2 workers running tasks, as if all workers were busy doing something, but nothing was actually happening. It seemed work had been queued, but was not being performed.

After looking at the logs for a given task in CloudWatch (which has the added benefit of including times in the log), there's a 60 second sleep after SIGTERM to when the process is finally killed with SIGKILL.

2021-01-23T15:00:02.682Z | Marking task as SUCCESS. dag_id=xxxxxxxx, task_id=xxxxxxx, execution_date=20210123T140000, start_date=20210123T150001, end_date=20210123T150002
-- | --
  | 2021-01-23T15:00:02.715Z | 0 downstream tasks scheduled from follow-on schedule check
  | 2021-01-23T15:00:06.606Z | State of this instance has been externally set to success. Terminating instance.
  | 2021-01-23T15:00:06.607Z | Sending Signals.SIGTERM to GPID 155
  | 2021-01-23T15:01:06.617Z | process psutil.Process(pid=155, name='airflow task ru', status='sleeping', started='15:00:01') did not respond to SIGTERM. Trying SIGKILL
  | 2021-01-23T15:01:06.625Z | Process psutil.Process(pid=155, name='airflow task ru', status='terminated', exitcode=<Negsignal.SIGKILL: -9>, started='15:00:01') (155) terminated with exit code Negsignal.SIGKILL
  | 2021-01-23T15:01:06.625Z | Task exited with return code Negsignal.SIGKILL

I imagine it's the configuration parameter KILLED_TASK_CLEANUP_TIME and it's default value of 60 that influences that sleep.

https://github.com/apache/airflow/blob/master/airflow/utils/process_utils.py#L42-L52

[Miksu82]

It also seems that this issues sets all the JobRuns to have failed state although the TaskInstance is correctly marked as success

[density]

We're also experiencing this issue with ECSOperator and CloudWatch logging on Airflow 2.0.2. Changing stopTimeout in our ECS config didn't fix the issue and it doesn't seem to always set the DAG run to failed for us like it does for @Miksu82.

[andormarkus]

Hi @potiuk, Who can help us with this bug?

[potiuk]

Maybe this is something the Amazon team can take a look at @subashcanapathy ? I think that's one of the obvious candidates that someone from AWS could help with since this is CloudWatch integration problem.

[ashb]

This might be fixed by #16289 -- one thing to try to see if that is the case is to disable the mini scheduler run by setting AIRFLOW__SCHEDULER__SCHEDULE_AFTER_TASK_EXECUTION=False

[andormarkus]

Should I set AIRFLOW__SCHEDULER__SCHEDULE_AFTER_TASK_EXECUTION=False in 2.0.2 or wait till #16289 is released?
Is #16289 part of 2.1.1 or we have to wait till 2.1.2?