Repository navigation
Many running task instances are cleared by the new scheduler when an old scheduler is terminated and its health check server is periodically requested #39088
Description
Apache Airflow version
Other Airflow 2 version (please specify below)
If "Other Airflow 2 version" selected, which one?
First confirmed with 2.5.0.
Now, confirmed that this also happens on 2.8.4
What happened?
I am running Airflow 2.5.0 with Kubernetes executor.
Recently, I have enable the health check server of the scheduler and configured a blackbox exporter which sends a request to check if the scheduler is healthy or not every 6-7seconds.
Normally, everything works fine.
However, when a new deployment is rolled out, the old scheduler is terminated and a new one is created, I found that many running task instances are cleared, i.e: the work pods are terminated and up to retry (some of them are heavy tasks, so this is quite bad for us).
And if I disable the blackbox exporter (ie: stop sending GET requests to the health server of the scheduler), the issue won't happen (no cleared task instances, just adopted). So I am considering there is something wrong with the logic to determine which task instances should be cleared instead of adopted.
Log from the new scheduler
[2024-04-17T08:14:24.568+0000] {scheduler_job.py:1463} INFO - Reset the following 102 orphaned TaskInstances:
Log from a worker pod
[2024-04-17, 16:56:29 JST] {local_task_job.py:223} WARNING - State of this instance has been externally set to restarting. Terminating instance.
[2024-04-17, 16:56:29 JST] {process_utils.py:129} INFO - Sending Signals.SIGTERM to group 92. PIDs of all processes in the group: [350, 92]
[2024-04-17, 16:56:29 JST] {process_utils.py:84} INFO - Sending the signal Signals.SIGTERM to group 92
[2024-04-17, 16:56:29 JST] {taskinstance.py:1483} ERROR - Received SIGTERM. Terminating subprocesses.
[2024-04-17, 16:56:29 JST] {taskinstance.py:1772} ERROR - Task failed with exception
Traceback (most recent call last):
...
File "/usr/local/lib/python3.10/site-packages/airflow/models/taskinstance.py", line 1485, in signal_handler
raise AirflowException("Task received SIGTERM signal")
airflow.exceptions.AirflowException: Task received SIGTERM signal
What you think should happen instead?
I expect that the running task instances should be adopted correctly by the new scheduler so that the tasks can continue without being interrupted.
How to reproduce
I described above.
- Deploy with helm-chart and having many running task instances
- setup an exporter to send a request to the scheduler every 6-7 seconds
- Not HA mode, just a single scheduler.
Operating System
CentOS 7.9
Versions of Apache Airflow Providers
- 2.5.0
- 2.8.4
Deployment
Official Apache Airflow Helm Chart
Deployment details
- helm-chart version 1.7.0 with some customizations (to add an ingress and a service for the health check server of scheduler)
- a single scheduler
scheduler section configuration:
enable_health_check: true
scheduler_health_check_server_port: 8974
job_heartbeat_sec: 45
scheduler_heartbeat_sec: 30
scheduler_health_check_threshold: 90
Anything else?
The issue does not happen 100% when a new deployment is rolled out.
Up to now, 3 of 5 times (60%)
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
Activity
[-]Many running task instances are cleared by the new scheduler when an old scheduler is terminated and it health check server is periodically requested [/-][+]Many running task instances are cleared by the new scheduler when an old scheduler is terminated and its health check server is periodically requested [/+]tanvn commentedon Apr 17, 2024
@potiuk @ephraimbuddy
Hi, do you even have a clue about this?
tanvn commentedon Apr 17, 2024
I also checked the log of the scheduler
which makes me believe that the following code block was executed successfully
https://github.com/apache/airflow/blob/2.5.0/airflow/executors/kubernetes_executor.py#L749-L765
and pod_id is removed from the dict:
pod_ids.pop(pod_id)so it is weird that it is included by
tis_to_flushlater 🤔tanvn commentedon Apr 17, 2024
And @dstandish
it seems that this issue is related to the health check server of the scheduler so I wonder if you might have any idea on this 🙇
dstandish commentedon Apr 17, 2024
Hi @tanvn
It seems you've made some progress with your repro scenario. What I would recommend doing is continue digging in. Add more logging to try to see exactly what component is taking what action and based on what information. Do you think you can try that? You can either run locally in a virtualenv based on airflow main, or you can check out a specific version and then create a patch which you can apply in your dockerfile if running on helm (or you can mount airflow into your containers). I'd be happy to help you with any dev setup stuff but it seems like you will be able to identify the root cause here so i want to encourage you to keep going at it.
RNHTTR commentedon Apr 17, 2024
@tanvn Can you check the audit logs for a task with the following log?
It's suspicious that the scheduler restarting resulted in this behavior it's not happening consistently.
tanvn commentedon Apr 18, 2024
@dstandish
Thanks! Yes, I believe I can reproduce on my dev environment and I want to build a docker image from the source code, if there is a document, I would appreciate if you could share with me (cc @potiuk )
@RNHTTR
As the task above has too many audit logs, I will give you an example of a different task (but the issue is totally the same)
here is its log
And below is the audit log for the task during that time
(for the sake of security, I have replaced the real names with dummy ones)
tanvn commentedon Apr 18, 2024
I managed to reproduce this issue on my development environment by creating a DAG with about 100 tasks. When there are about 15 running tasks, I run a helm command to upgrade the deployment, then the old scheduler is terminated and a new one is created and running.
The log shows that
but later, the corresponding task is still reset:
And the task is terminated later
The cause is remaining unclear but I can confirm that the issue can be reproduced (so maybe this is a bug).
tanvn commentedon Apr 18, 2024
Just tested with Airflow 2.8.4 and confirmed that the issue still happens.
log on the task instance:
tanvn commentedon Apr 18, 2024
@dstandish
I would like to build a Docker image from the source code (which I am going to add some modifications for testing) on my Macbook (Apple M2), is there any document guide for this?I would like to use CentOS 7 as a base image.
Never mind, I found a way 😄
RNHTTR commentedon Apr 18, 2024
@tanvn Thanks for the extra details! I've assigned you to the Issue.
paramjeet01 commentedon Apr 21, 2024
@tanvn @RNHTTR , Could this issue be related to the one I raised : #39096
We are running 8 schedulers and we see this issue happening often , where the task is killed by SIGTERM and the pod is still running. When the task is retried again , we have error log stating the labels already exists and we see the pod is still running.
paramjeet01 commentedon Apr 23, 2024
How did you solve the issue @tanvn
tanvn commentedon Apr 23, 2024
@paramjeet01
I use pip to install from the source code locally:
airflow/INSTALL
Line 73 in 4ae85d7
on a docker image. The base docker image is https://hub.docker.com/r/centos/python-38-centos7 (or you can use CentOS7 then install Python with the version you want on it)
There are some required packages/libraries in order to install Airflow on CentOS but it is not that difficult.
RNHTTR commentedon Apr 23, 2024
@tanvn Can you share the full traceback?
tanvn commentedon Apr 23, 2024
@RNHTTR
Tested and reproduced the issue on Airflow 2.8.4, below is the error logs from scheduler and one terminated pod
error log of
test__orphaned_test_dag.select_26Task instance worker pod:Logs on the scheduler containing the pod name
test-orphaned-test-dag-select-26-v3hdab2d:tanvn commentedon May 3, 2024
I think I found the cause of this issue.
The logic of
adopt_or_reset_orphaned_tasksis called 2 times in a very short time due to the use ofrun_with_db_retrieshttps://github.com/apache/airflow/blob/2.8.4/airflow/jobs/scheduler_job_runner.py#L1610
When the first attempt tried to update task instances in my MySQL, a
MySQLdb.OperationalErrorerror happened,and the second attempt was carried out almost immediately (0.4467290363932428 seconds, as shown in the log)
https://github.com/apache/airflow/blob/2.8.4/airflow/jobs/scheduler_job_runner.py#L1651-L1679
In the second attempt, while the pods have been adopted already so the corresponding task instances are not removed from
tis_to_flush_by_keyand were added totis_to_flushdue totis_to_flush.extend(tis_to_flush_by_key.values())https://github.com/apache/airflow/blob/2.8.4/airflow/providers/cncf/kubernetes/executors/kubernetes_executor.py#L553-L575
Here is the logs
tanvn commentedon May 4, 2024
@RNHTTR
Hi, I created a PR to fix this issue: #39406
PTAL at your convenience.