Tasks Stuck in Running state after execution complete

[jaymekb-eb]

We just upgraded from version 2.6.3 to 2.10.2. After the upgrade we're seeing much longer run times for DAGs during peak hours (we have thousands of tasks that kick off every 4 hours). During non-peak hours, the DAGs seem to have comparable run times to pre-upgrade.

While the DAG is still running, we will see a task which typically completes in <1 minute appear to be stuck in running state for 40-50 minutes, but the logs show that the execution is complete. Eventually the task is marked as success and then it will show a run time of the expected ~30 seconds.

Here are the logs for the task in the Post-Execution portion

[2024-10-18, 08:04:06 UTC] {taskinstance.py:340} ▼ Post task execution logs
[2024-10-18, 08:04:06 UTC] {taskinstance.py:352} INFO - Marking task as SUCCESS. dag_id=web_ingestion_v3, task_id=web_geoservicetimezonedbmissgooglehit_action_ingestion.get_metadata, run_id=scheduled__2024-10-18T07:00:00+00:00, execution_date=20241018T070000, start_date=20241018T080355, end_date=20241018T080406
[2024-10-18, 08:04:06 UTC] {taskinstance.py:1563} INFO - Executing callback at index 0: EbPagerDutyResolveNotifier
[2024-10-18, 08:04:06 UTC] {eb_pagerduty_resolve_notifier.py:46} INFO - Running PagerDuty Resolve Notifier: web_ingestion_v3_web_geoservicetimezonedbmissgooglehit_action_ingestion.get_metadata_scheduled__2024-10-18T07:00:00+00:00
[2024-10-18, 08:04:06 UTC] {eb_pagerduty_resolve_notifier.py:49} INFO - Current Try Number: 1 | resolve_on_first_try: False
[2024-10-18, 08:04:06 UTC] {eb_pagerduty_events_hook.py:44} INFO - Looking up connection pagerdutyapiconnection-warnings_prod
[2024-10-18, 08:04:06 UTC] {base.py:84} INFO - Retrieving connection 'pagerdutyapiconnection-warnings_prod'
[2024-10-18, 08:04:06 UTC] {eb_pagerduty_events_hook.py:64} INFO - Resolving PD with dedup key: web_ingestion_v3_web_geoservicetimezonedbmissgooglehit_action_ingestion.get_metadata_scheduled__2024-10-18T07:00:00+00:00 
[2024-10-18, 08:55:18 UTC] {local_task_job_runner.py:266} INFO - Task exited with return code 0
[2024-10-18, 08:55:18 UTC] {local_task_job_runner.py:245} ▲▲▲ Log group end

You can see a 50 minute period between the logs in our success_callback and the local_task_job_runner marking the task as a success.

I can also see in the Event log that the Success log was written at 8:55

This isn't happening for all tasks and it's not consistent which ones it's happening with, but we've seen the behavior with several tasks across several DAGs. This seems to be impacting concurrency across the instance because these tasks are taking up slots in the Pool while not actually doing anything.

I'm curious if anyone has tips on how to fix this or other places to look?

As a next step and bandaid, I'm planning to add execution_timeout values for these tasks, but that is only possible for a few types of tasks we have - the impacted tasks currently seem to fall into that bucket.

Details about deployment:
Executor: CeleryKubernetesExecutor - impacted tasks seem to all be running on Celery workers
Metadata Database: AWS RDS MySql
Airflow Helm chart: 1.10 (we're upgrading to 1.15 now)

[jaymekb-eb]

I finally figured out that the issue was in our success_callback which makes a call to the pagerduty API with a resolve event. We only want to do this if it's a successful retry. In version 2.6.3, the try_number in the context was 2 when it was actually the first attempt. In version 2.10.2, try_number is more accurately 1 when it's the first attempt. Since we were sending an event to the PD API for all tasks completing on the first try, we started hitting rate limits. The pdpyras package will, by default, retry the request infinitely when the response is a 429 (indicating rate limit was hit).

[potiuk]

Thanks for letting us know. Indeed that retry_num has been fixed. Might be helpful to see the case for others who might have similar issues.