You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "rcrchawla (via GitHub)" <gi...@apache.org> on 2026/04/06 07:08:43 UTC
Re: [D] Airflow task failed but spark kube app is running [airflow]
GitHub user rcrchawla added a comment to the discussion: Airflow task failed but spark kube app is running
Hi @shaealh
As discussed we have lowered down the concurrency and it is working fine but we faced one challenge which is one time only where scheduler is launching a task (Spark Kubernetes Operator) which is working fine for few minutes and after that worker is unable to send the signal and it retried 5 times and worker got the message "Server error task instance is already running somewhere else" and where it launched another pid for same task _id now we see in the airflow logs this task wait for getting the resource to launch the driver where we have set the property "startup_timeout_seconds" to 40 minutes but in the logs after it waiting it killed the task now not sure why it has killed the task.
Could you please suggest anything by seeing the below summarized logs :
[Uploading 20260326.zip…]()
airflow-worker-1
2026-03-26 02:14 -- 173a1136-b645-4d67-a13a-a485a3704efc -- load_track_group_id_nerd_portals -- 019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:26.905924 [warning ] Failed to send heartbeat. Will be retried [supervisor] failed_heartbeats=1 max_retries=3 ti_id=UUID('019d277e-99e9-763d-b75b-d6cd75120881')
2026-03-26 02:47:57.527466 [warning ] Server error [airflow.sdk.api.client] detail={'detail': {'reason': 'not_running', 'message': 'TI is no longer in the running state and task should terminate', 'current_state': None}}
2026-03-26 02:47:57.527755 [error ] Server indicated the task shouldn't be running anymore [supervisor] detail={'detail': {'reason': 'not_running', 'message': 'TI is no longer in the running state and task should terminate', 'current_state': None}} status_code=409 ti_id=UUID('019d277e-99e9-763d-b75b-d6cd75120881')
2026-03-26 02:47:58.194844 [info ] Task execute_workload[3fb3128a-86c9-43bc-a1fb-3b0a6dcbcec4] received [celery.worker.strategy]
2026-03-26 02:47:58.228603 [info ] [3fb3128a-86c9-43bc-a1fb-3b0a6dcbcec4] Executing workload in Celery: token='eyJ***' ti=TaskInstance(id=UUID('019d277e-99e9-763d-b75b-d6cd75120881'), task_id='ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals', dag_id='segment-groupid-1', run_id='scheduled__2026-03-26T00:15:00+00:00', try_number=2, map_index=-1, pool_slots=1, queue='default', priority_weight=13, executor_config=None, parent_context_carrier={}, context_carrier={}, queued_dttm=datetime.datetime(2026, 3, 26, 2, 14, 17, 330486, tzinfo=TzInfo(UTC))) dag_rel_path=PurePosixPath('segment_groupid_1.py') bundle_info=BundleInfo(name='dags-folder', version=None) log_path='dag_id=segment-groupid-1/run_id=scheduled__2026-03-26T00:15:00+00:00/task_id=ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals/attempt=2.log' type='ExecuteTask' [airflow.providers.celery.executors.celery_executor_utils]
2026-03-26 02:47:58.256886 [info ] Secrets backends loaded for worker [supervisor]
2026-03-26 02:48:02.577882 [info ] Task execute_workload[173a1136-b645-4d67-a13a-a485a3704efc] succeeded in 2025.1995898000896s: None [celery.app.trace]
2026-03-26 02:48:10.794292 [info ] Task finished [supervisor] duration=12.537848281674087 exit_code=0 final_state=failed
2026-03-26 02:48:10.810689 [info ] Task execute_workload[3fb3128a-86c9-43bc-a1fb-3b0a6dcbcec4] succeeded in 12.614215551875532s: None [celery.app.trace]
2026-03-26 02:49:55.420123 [info ] Task finished [supervisor] duration=36.28673866484314 exit_code=0 final_state=success
--------------------------------------------------------------------------------------------------------
api_server
---------------------------------------------
2026-03-26 02:45:47 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1193430 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:45:47 [debug ] Retrieved current task state current_hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local current_pid=1193430 state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:45:47 [debug ] Heartbeat updated state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:60936 - "PUT /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/heartbeat HTTP/1.1" 204 No Content
2026-03-26 02:46:38 [debug ] Retrieved current task state current_hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local current_pid=1193430 state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:46:38 [debug ] Heartbeat updated state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:50958 - "PUT /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/heartbeat HTTP/1.1" 204 No Content
2026-03-26 02:46:58 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1193430 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:13 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1193430 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:21 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1193430 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:27 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1193430 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:55 [debug ] Retrieved current task state current_hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local current_pid=1193430 state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:55 [debug ] Heartbeat updated state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
Taskk failed with below error
2026-03-26 02:47:57 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1193430 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:57 [debug ] Retrieved current task state current_hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local current_pid=1193430 state=None ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:57 [warning ] Task not in running state current_state=None ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:54322 - "PUT /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/heartbeat HTTP/1.1" 409 Conflict
New task launched for same task id
2026-03-26 02:47:58 [debug ] Starting task instance run hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1201129 ti_id=019d277e-99e9-763d-b75b-d6cd75120881 unixname=airflow
2026-03-26 02:47:58 [debug ] Starting task instance run hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1201129 ti_id=019d277e-99e9-763d-b75b-d6cd75120881 unixname=airflow
2026-03-26 02:47:58 [debug ] Retrieved task instance details dag_id=segment-groupid-1 state=queued task_id=ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:58 [info ] Task started hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local previous_state=queued ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:58 [info ] Task instance state updated rows_affected=1 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:54334 - "PATCH /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/run HTTP/1.1" 200 OK
2026-03-26 02:47:58 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1201129 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:58 [debug ] Retrieved current task state current_hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local current_pid=1201129 state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:47:58 [debug ] Heartbeat updated state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:54334 - "PUT /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/heartbeat HTTP/1.1" 204 No Content
2026-03-26 02:48:09 [debug ] Processing heartbeat hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local pid=1201129 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:48:09 [debug ] Retrieved current task state current_hostname=airflow-worker-1.airflow-worker.de-services.svc.cluster.local current_pid=1201129 state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:48:09 [debug ] Heartbeat updated state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:35238 - "PUT /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/heartbeat HTTP/1.1" 204 No Content
INFO: 172.26.145.209:35238 - "GET /execution/connections/smtp_default HTTP/1.1" 200 OK
2026-03-26 02:48:10 [debug ] Updating task instance state new_state=failed ti_id=019d277e-99e9-763d-b75b-d6cd75120881
2026-03-26 02:48:10 [debug ] Retrieved current task instance state max_tries=0 previous_state=running ti_id=019d277e-99e9-763d-b75b-d6cd75120881 try_number=2
2026-03-26 02:48:10 [debug ] Processing heartbeat hostname=airflow-worker-2.airflow-worker.de-services.svc.cluster.local pid=1128588 ti_id=019d278c-5124-76a1-895b-d904aa955a06
2026-03-26 02:48:10 [info ] Task instance state updated new_state=failed rows_affected=1 ti_id=019d277e-99e9-763d-b75b-d6cd75120881
INFO: 172.26.145.209:35238 - "PATCH /execution/task-instances/019d277e-99e9-763d-b75b-d6cd75120881/state HTTP/1.1" 204 No Content
scheduler
-------------
[2026-03-26T02:14:17.329+0000] {scheduler_job_runner.py:451} INFO - 2 tasks up for execution:
<TaskInstance: segment-groupid-2.etl_load_to_ods_group_id_2.branching_etl_step schedsuled__2026-03-26T00:45:00+00:00 [scheduled]>
<TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [scheduled]>
[2026-03-26T02:14:17.330+0000] {scheduler_job_runner.py:662} INFO - Setting the following tasks to queued state:
<TaskInstance: segment-groupid-2.etl_load_to_ods_group_id_2.branching_etl_step scheduled__2026-03-26T00:45:00+00:00 [scheduled]>
<TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [scheduled]>
[2026-03-26T02:14:17.333+0000] {scheduler_job_runner.py:768} INFO - Trying to enqueue tasks: [<TaskInstance: segment-groupid-2.etl_load_to_ods_group_id_2.branching_etl_step scheduled__2026-03-26T00:45:00+00:00 [scheduled]>, <TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [scheduled]>] for executor: CeleryExecutor(parallelism=32)
[2026-03-26T02:14:17.462+0000] {scheduler_job_runner.py:811} INFO - Received executor event with state queued for task instance TaskInstanceKey(dag_id='segment-groupid-1', task_id='ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals', run_id='scheduled__2026-03-26T00:15:00+00:00', try_number=1, map_index=-1)
[2026-03-26T02:47:55.913+0000] {scheduler_job_runner.py:2210} INFO - Reset the following 2 orphaned TaskInstances:
<TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [running]>
<TaskInstance: Document_pipeline_kube.CORE.document_parser scheduled__2026-03-26T00:30:00+00:00 [running]>
[2026-03-26T02:47:58.140+0000] {scheduler_job_runner.py:451} INFO - 2 tasks up for execution:
<TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [scheduled]>
[2026-03-26T02:47:58.141+0000] {scheduler_job_runner.py:662} INFO - Setting the following tasks to queued state:
<TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [scheduled]>
[2026-03-26T02:47:58.147+0000] {scheduler_job_runner.py:768} INFO - Trying to enqueue tasks: [<TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [scheduled]>, <TaskInstance: Document_pipeline_kube.CORE.document_parser scheduled__2026-03-26T00:30:00+00:00 [scheduled]>] for executor: CeleryExecutor(parallelism=32)
[2026-03-26T02:47:58.322+0000] {scheduler_job_runner.py:811} INFO - Received executor event with state queued for task instance TaskInstanceKey(dag_id='segment-groupid-1', task_id='ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals', run_id='scheduled__2026-03-26T00:15:00+00:00', try_number=2, map_index=-1)
[2026-03-26T02:47:58.336+0000] {scheduler_job_runner.py:843} INFO - Setting external_id for <TaskInstance: segment-groupid-1.ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals scheduled__2026-03-26T00:15:00+00:00 [running]> to 3fb3128a-86c9-43bc-a1fb-3b0a6dcbcec4
[2026-03-26T02:48:04.417+0000] {scheduler_job_runner.py:811} INFO - Received executor event with state success for task instance TaskInstanceKey(dag_id='segment-groupid-1', task_id='ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals', run_id='scheduled__2026-03-26T00:15:00+00:00', try_number=1, map_index=-1)
[2026-03-26T02:48:04.429+0000] {scheduler_job_runner.py:853} INFO - TaskInstance Finished: dag_id=segment-groupid-1, task_id=ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals, run_id=scheduled__2026-03-26T00:15:00+00:00, map_index=-1, run_start_date=2026-03-26 02:47:58.263013+00:00, run_end_date=None, run_duration=None, state=running, executor=CeleryExecutor(parallelism=32), executor_state=success, try_number=1, max_tries=0, pool=default_pool, queue=default, priority_weight=13, operator=SparkKubernetesOperator, queued_dttm=2026-03-26 02:47:58.142052+00:00, scheduled_dttm=2026-03-26 02:47:58.060945+00:00,queued_by_job_id=2414479, pid=1201129
[2026-03-26T02:48:12.148+0000] {scheduler_job_runner.py:811} INFO - Received executor event with state success for task instance TaskInstanceKey(dag_id='segment-groupid-1', task_id='ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals', run_id='scheduled__2026-03-26T00:15:00+00:00', try_number=2, map_index=-1)
[2026-03-26T02:48:12.159+0000] {scheduler_job_runner.py:853} INFO - TaskInstance Finished: dag_id=segment-groupid-1, task_id=ODS_Load_group_id_nerd_portals.load_track_group_id_nerd_portals, run_id=scheduled__2026-03-26T00:15:00+00:00, map_index=-1, run_start_date=2026-03-26 02:47:58.263013+00:00, run_end_date=2026-03-26 02:48:10.755668+00:00, run_duration=12.4927, state=failed, executor=CeleryExecutor(parallelism=32), executor_state=success, try_number=2, max_tries=0, pool=default_pool, queue=default, priority_weight=13, operator=SparkKubernetesOperator, queued_dttm=2026-03-26 02:47:58.142052+00:00, scheduled_dttm=2026-03-26 02:47:58.060945+00:00,queued_by_job_id=2414479, pid=1201129
GitHub link: https://github.com/apache/airflow/discussions/63298#discussioncomment-16461428
----
This is an automatically sent email for commits@airflow.apache.org.
To unsubscribe, please send an email to: commits-unsubscribe@airflow.apache.org