airflow: Copy of [AIRFLOW-5071] JIRA: Thousands of Executor reports task instance X finished (success) although the task says its queued. Was the task killed externally?

Apache Airflow version: 1.10.9

Kubernetes version (if you are using kubernetes) (use kubectl version): Server: v1.10.13, Client: v1.17.0

Environment:

  • Cloud provider or hardware configuration: AWS
  • OS (e.g. from /etc/os-release): Debian GNU/Linux 9 (stretch)
  • Kernel (e.g. uname -a): Linux airflow-web-54fc4fb694-ftkp5 4.19.123-coreos #1 SMP Fri May 22 19:21:11 -00 2020 x86_64 GNU/Linux
  • Others: Redis, CeleryExecutor

What happened:

In line with the guidelines laid out in AIRFLOW-7120, I’m copying over a JIRA for a bug that has significant negative impact on our pipeline SLAs. The original ticket is AIRFLOW-5071 which has a lot of details from various users who use ExternalTaskSensors in reschedule mode and see their tasks going through the following unexpected state transitions:

running -> up_for_reschedule -> scheduled -> queued -> up_for_retry

In our case, this issue seems to affect approximately ~2000 tasks per day.

Screenshot 2020-09-08 at 09 01 03

What you expected to happen:

I would expect that tasks would go through the following state transitions instead: running -> up_for_reschedule -> scheduled -> queued -> running

How to reproduce it:

Unfortunately, I don’t have configuration available that could be used to easily reproduce the issue at the moment. However, based on the thread in AIRFLOW-5071, the problem seems to arise in deployments that use a large number of sensors in reschedule mode.

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Reactions: 25
  • Comments: 60 (25 by maintainers)

Most upvoted comments

We have just introduced ExternalTaskSensor into our pipeline and faced the same issue. When initially tested on our dev instance (~200 DAGs) it worked fine, after running it on our prod environment (~400 DAGs) it was always failing after reschedule.

After digging into the code, it looks that this is simply race condition in the scheduler.

We have child_dag.parent_dag_completed task that waits for business process to complete calculations in parent_dag, task execution logs:

[2020-10-01 11:48:03,038] {taskinstance.py:669} INFO - Dependencies all met for <TaskInstance: child_dag.parent_dag_completed 2020-09-30T11:45:00+00:00 [queued]>
[2020-10-01 11:48:03,065] {taskinstance.py:669} INFO - Dependencies all met for <TaskInstance: child_dag.parent_dag_completed 2020-09-30T11:45:00+00:00 [queued]>
[2020-10-01 11:48:03,066] {taskinstance.py:879} INFO - 
--------------------------------------------------------------------------------
[2020-10-01 11:48:03,066] {taskinstance.py:880} INFO - Starting attempt 1 of 1
[2020-10-01 11:48:03,066] {taskinstance.py:881} INFO - 
--------------------------------------------------------------------------------
[2020-10-01 11:48:03,095] {taskinstance.py:900} INFO - Executing <Task(ExternalTaskSensor): parent_dag_completed> on 2020-09-30T11:45:00+00:00
[2020-10-01 11:48:03,100] {standard_task_runner.py:53} INFO - Started process 26131 to run task
[2020-10-01 11:48:03,235] {logging_mixin.py:112} INFO - Running %s on host %s <TaskInstance: child_dag.parent_dag_completed 2020-09-30T11:45:00+00:00 [running]> ip-10-200-100-113.eu-west-1.compute.internal
[2020-10-01 11:48:03,318] {external_task_sensor.py:117} INFO - Poking for parent_dag on 2020-09-30T11:45:00+00:00 ... 
[2020-10-01 11:48:03,397] {taskinstance.py:1136} INFO - Rescheduling task, marking task as UP_FOR_RESCHEDULE
[2020-10-01 11:48:12,994] {logging_mixin.py:112} INFO - [2020-10-01 11:48:12,993] {local_task_job.py:103} INFO - Task exited with return code 0
[2020-10-01 11:50:53,744] {taskinstance.py:663} INFO - Dependencies not met for <TaskInstance: child_dag.parent_dag_completed 2020-09-30T11:45:00+00:00 [failed]>, dependency 'Task Instance State' FAILED: Task is in the 'failed' state which is not a valid state for execution. The task must be cleared in order to be run.
[2020-10-01 11:50:53,747] {logging_mixin.py:112} INFO - [2020-10-01 11:50:53,747] {local_task_job.py:91} INFO - Task is not able to be run

Scheduler logs:

<TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [scheduled]>
[2020-10-01 11:47:59,428] {scheduler_job.py:1010} INFO - DAG child_dag has 0/16 running and queued tasks
<TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [scheduled]>
<TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [queued]>
[2020-10-01 11:47:59,565] {scheduler_job.py:1170} INFO - Sending ('child_dag', 'parent_dag_completed', datetime.datetime(2020, 9, 30, 11, 45, tzinfo=<Timezone [UTC]>), 1) to executor with priority 3 and queue default
[2020-10-01 11:47:59,565] {base_executor.py:58} INFO - Adding to queue: ['airflow', 'run', 'child_dag', 'parent_dag_completed', '2020-09-30T11:45:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/airflow/dags/291a327d-5d46-4cf5-87cf-4bad036f56fa_1.py']
<TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [scheduled]>
[2020-10-01 11:50:50,118] {scheduler_job.py:1010} INFO - DAG child_dag has 0/16 running and queued tasks
<TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [scheduled]>
<TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [queued]>
[2020-10-01 11:50:50,148] {scheduler_job.py:1170} INFO - Sending ('child_dag', 'parent_dag_completed', datetime.datetime(2020, 9, 30, 11, 45, tzinfo=<Timezone [UTC]>), 1) to executor with priority 3 and queue default
[2020-10-01 11:50:50,148] {base_executor.py:58} INFO - Adding to queue: ['airflow', 'run', 'child_dag', 'parent_dag_completed', '2020-09-30T11:45:00+00:00', '--local', '--pool', 'default_pool', '-sd', '/usr/local/airflow/dags/291a327d-5d46-4cf5-87cf-4bad036f56fa_1.py']
[2020-10-01 11:50:50,595] {scheduler_job.py:1313} INFO - Executor reports execution of child_dag.parent_dag_completed execution_date=2020-09-30 11:45:00+00:00 exited with status success for try_number 1
[2020-10-01 11:50:50,599] {scheduler_job.py:1330} ERROR - Executor reports task instance <TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [queued]> finished (success) although the task says its queued. Was the task killed externally?
[2020-10-01 11:50:50,803] {taskinstance.py:1145} ERROR - Executor reports task instance <TaskInstance: child_dag.parent_dag_completed 2020-09-30 11:45:00+00:00 [queued]> finished (success) although the task says its queued. Was the task killed externally?
[2020-10-01 11:50:50,804] {taskinstance.py:1202} INFO - Marking task as FAILED.dag_id=child_dag, task_id=parent_dag_completed, execution_date=20200930T114500, start_date=20201001T114803, end_date=20201001T115050

From scheduler log it’s visible that event from executor is processed after task is already queued for the second time.

Logic related to those logs is here:

    def _validate_and_run_task_instances(self, simple_dag_bag):
        if len(simple_dag_bag.simple_dags) > 0:
            try:
                self._process_and_execute_tasks(simple_dag_bag) # <-- task state is changed to queued here
            except Exception as e:
                self.log.error("Error queuing tasks")
                self.log.exception(e)
                return False

        # Call heartbeats
        self.log.debug("Heartbeating the executor")
        self.executor.heartbeat()

        self._change_state_for_tasks_failed_to_execute()

        # Process events from the executor
        self._process_executor_events(simple_dag_bag) # <-- notification of previous execution is processed and there is state mismatch 
        return True

This is the place where task state is changes:

    def _process_executor_events(self, simple_dag_bag, session=None):
       
       # ...
       
                if ti.try_number == try_number and ti.state == State.QUEUED:
                    msg = ("Executor reports task instance {} finished ({}) "
                           "although the task says its {}. Was the task "
                           "killed externally?".format(ti, state, ti.state))
                    Stats.incr('scheduler.tasks.killed_externally')
                    self.log.error(msg)
                    try:
                        simple_dag = simple_dag_bag.get_dag(dag_id)
                        dagbag = models.DagBag(simple_dag.full_filepath)
                        dag = dagbag.get_dag(dag_id)
                        ti.task = dag.get_task(task_id)
                        ti.handle_failure(msg)
                    except Exception:
                        self.log.error("Cannot load the dag bag to handle failure for %s"
                                       ". Setting task to FAILED without callbacks or "
                                       "retries. Do you have enough resources?", ti)
                        ti.state = State.FAILED
                        session.merge(ti)
                        session.commit()

Unfortunately I think that moving _process_executor_events before _process_and_execute_tasks would not solve the issue as event might arrive from executor while _process_and_execute_tasks is executing. Increasing poke_interval reduces chance of this race condition happening when scheduler is under a heavy load.

I’m not too familiar with Airflow code base, but it seems that the root cause is the way how reschedule works and the fact that try_number is not changing. Because of that scheduler thinks that event for past execution is for the ongoing one.

Hello. I am using airflow 2.0 and just ran into this error.

How can I fix it??

Just summarising what others have reported worked for them:

  1. Set worker_concurrency to match the CPU number and worker_autoscale to “4,2”.
  2. Increase the poke_interval value for the sensors to 5 minutes (from the default 1 minute).
  3. Reduce the scheduler looping time(dag processing time, etc) or increase the sensor task reschedule.

After STRUGLING, We found a method to 100% reproduce this issue !!!

tl;dr

https://github.com/apache/airflow/blob/9ac742885ffb83c15f7e3dc910b0cf9df073407a/airflow/models/taskinstance.py#L1253

Add a raise to simulate db error which will likely happen when the DB is under great pressure.

Then you will get this issue Was the task killed externally in all the time.

Conditions:

  • Airflow 2.2
  • Celery Executor

It’s becasue the worker use a local task job which will spwan a child process to execute the job. The parent process set the task from Queued to Running State. However, when the prepare work for the parent process failed, it will lead to this error directly.

related code is here: https://github.com/apache/airflow/blob/2.2.2/airflow/jobs/local_task_job.py#L89

Hi @turbaszek, any finding on this? We have a CeleryExecutor + Redis setup with three workers (apache-airflow 1.10.12). The airflow-scheduler log has a lot of lines like this. I remember this was already a problem when we were using older versions such as 1.10.10. It’s just we never paid much attention to it.

{taskinstance.py:1150} ERROR - Executor reports task instance <TaskInstance: ... [queued]> finished (success) although the task says its queued. Was the task killed externally?

Same with others in this thread, we have a lot of sensors in “reschedule” mode with poke_interval set to 60s. These are the ones that most often hit this error. So far our workaround has been to add a retries=3 to these sensors. That way when this error happens it retries and we don’t get any spam. This is definitely not a great long term solution though. Such sensors go into up_for_retry state when this happen.

I also tried to tweak these parameters. They don’t seem to matter much as far as this error is concerned:

parallelism = 1024
dag_concurrency = 128
max_threads = 8

The way to reproduce this issue seems to be to create a DAG with a bunch of parallel reschedule sensors. And make the DAG slow to import. For example, like this. If we add a time.sleep(30) at the end to simulate the experience of slow-to-import DAGs, this error happens a lot for such sensors. You may also need to tweak the dagbag_import_timeout and dag_file_processor_timeout if adding the sleep causes dags to fail to import altogether.

When the scheduler starts to process this DAG, we then start to see the above error happening to these sensors. And the go into up_for_retry.

import datetime
import pendulum
import time

from airflow.models.dag import DAG
from airflow.contrib.sensors.python_sensor import PythonSensor

with DAG(
    dag_id="test_dag_slow",
    start_date=datetime.datetime(2020, 9, 8),
    schedule_interval="@daily",
) as dag:
    sensors = [
        PythonSensor(
            task_id=f"sensor_{i}",
            python_callable=lambda: False,
            mode="reschedule",
            retries=2,
        ) for i in range(20)
    ]
    time.sleep(30)

we reviewed the code and found that in local_task_job.py, the parent process has a heatbeat_callback, and will check the state and child process return code of the task_instance.

However, theses lines may cover a bug?

image

image

The raw task command write back the taskintance’s state(like sucess) doesn’t mean the child process is finished(returned)?

So, in this heatbeat callback, there maybe a race condition when task state is filled back while the child process is not returned.

In this senario, the local task will kill the child process by mistake. And then, the scheduler will checkout this and report “task instance X finished (success) although the task says its queued. Was the task killed externally?”

this is a simple schematic diagram:

image

Same here with Airflow 2.0.1

@turbaszek Let me make a PR later~ We are doing pressure tests these days and this problem had appeared often.

@turbaszek I am currently testing Airflow v2.0.0b3 against the same DAGS we currently run on production against 1.10.12 and I can confirm that this is still an issue.

Combined with #12552 it makes the problem even worse too.

We also got the same error message. In our case, it turns out that we are using the same name for different dags. Changing different dags from as dag to like as dags1 and as dags2 solve the issue for us.

with DAG(
    "dag_name",
) as dag:

@yuqian90

I also tried to tweak these parameters. They don’t seem to matter much as far as this error is concerned:

parallelism = 1024
dag_concurrency = 128
max_threads = 8

The way to reproduce this issue seems to be to create a DAG with a bunch of parallel reschedule sensors. And make the DAG slow to import. For example, like this. If we add a time.sleep(30) at the end to simulate the experience of slow-to-import DAGs, this error happens a lot for such sensors. You may also need to tweak the dagbag_import_timeout and dag_file_processor_timeout if adding the sleep causes dags to fail to import altogether.

Those parameters won’t help you much. I was struggling to somehow workaround this issue and I believe I’ve found the right solution now. In my case the biggest hint while debugging was not scheduler/worker logs but the Celery Flower Web UI. We have a setup of 3 Celery workers, 4 CPU each. It often happened that Celery was running 8 or more python reschedule sensors on one worker but 0 on the others and that was the exact time when sensors started to fail. There are two Celery settings that are responsible for this behavior: worker_concurrency with a default value of “16” and worker_autoscale with a default value of “16,12” (it basically means that minimum Celery process # on the worker is 12 and can be scaled up to 16). With those set with default values Celery was configured to load up to 16 tasks (mainly reschedule sensors) to one node. After setting worker_concurrency to match the CPU number and worker_autoscale to “4,2” the problem is literally gone. Maybe that might be anothe clue for @turbaszek.

I’ve been trying a lot to setup a local docker compose file with scheduler, webserver, flower, postgres and RabbitMQ as a Celery backend but I was not able to replicate the issue as well. I tried to start a worker container with limited CPU to somehow imitate this situation, but I failed. There are in fact tasks killed and shown as failed in Celery Flower, but not with the “killed externally” reason.

We also run into this fairly often, despite not using any sensors. We only seemed to start getting this error once we changed our Airflow database to be in the cloud (AWS RDB); our Airflow webserver & scheduler runs on desktop workstations on-premises. As others have suggested in this thread, this is a very annoying problem that requires manual intervention.

@ghostbody any progress on determining if that’s the correct root cause?

I found that in the code of airflow/jobs/scheduler_job.py: https://github.com/apache/airflow/blob/main/airflow/jobs/scheduler_job.py#L535

           if ti.try_number == buffer_key.try_number and ti.state == State.QUEUED:
                Stats.incr('scheduler.tasks.killed_externally')
                msg = (
                    "Executor reports task instance %s finished (%s) although the "
                    "task says its %s. (Info: %s) Was the task killed externally?"
                )
                self.log.error(msg, ti, state, ti.state, info)

The scheduler checks the state of the task instance. When a task instance is rescheduled (e.g: an external sensor), its state transition up_for_reschedule -> scheduled -> queued -> running. If its state is queued and not moved to the running state, the scheduler will raise an error. So I think the code needs to be changed:

           if ti.try_number == buffer_key.try_number and (
                ti.state == State.QUEUED and not TaskReschedule.find_for_task_instance(ti, session=session)
            ):
                Stats.incr('scheduler.tasks.killed_externally')
                msg = (
                    "Executor reports task instance %s finished (%s) although the "
                    "task says its %s. (Info: %s) Was the task killed externally?"
                )
                self.log.error(msg, ti, state, ti.state, info)

Here is my PR: https://github.com/apache/airflow/pull/19123

Hello. I am using airflow 2.0 and just ran into this error.

How can I fix it??

Hello @karthik-raparthi, we also did experience similar issue with EFS. EFS is definitely not suited for a big airflow deployment, and we stopped having most of its issues when we moved to FSx File System. I therefore encourage you to move to this better solution 😃

(we had EFS 100 Mo/s provisioned throughout and still experiencing this)

Quite agree. There were multiple people reporting problems in huge airflow installation where EFS was used. I can also recommend (as usual) switching to Git Sync. I wrote an article about it https://medium.com/apache-airflow/shared-volumes-in-airflow-the-good-the-bad-and-the-ugly-22e9f681afca - especially when you are using Git to store your DAGs already, using shared volume is completely unnecessary and using Git Sync directly is far better solution.

airflow: 2.2.2 with mysql8、 HA scheduler、celery executor(redis backend)

From logs, it show that those ti reported this error killed externally (status: success) , were rescheduled!

  1. scheduler found a ti to scheduled (ti from None to scheduled)
  2. scheduler queued ti(ti from scheduled to queued)
  3. scheduler send ti to celery
  4. worker get ti
  5. worker found ti‘s state in mysql is scheduled https://github.com/apache/airflow/blob/2.2.2/airflow/models/taskinstance.py#L1224
  6. worker set this ti to None
  7. scheduler reschedule this ti( ti from None to scheduled)
  8. scheduler queue this ti( ti from scheduled to queued) ,but could not queue this ti to celery again, and found this ti success(in celery), so set it to failed

From mysql we get that: all failed task has no external_executor_id!

We use 5000 dags, each with 50 dummy task, found that, if the following two conditions are met,the probability of triggering this problem will highly increase:

  1. no external_executor_id was set to queued ti in celery https://github.com/apache/airflow/blob/2.2.2/airflow/jobs/scheduler_job.py#L537
    • This sql above has skip_locked, and some queued ti in celery may miss this external_executor_id.
  2. a scheduler loop cost very long(more than 60s), adopt_or_reset_orphaned_tasks judge that schedulerJob failed, and try adopt orphaned ti https://github.com/apache/airflow/blob/9ac742885ffb83c15f7e3dc910b0cf9df073407a/airflow/executors/celery_executor.py#L442

We do these tests:

  1. patch SchedulerJob. _process_executor_events , not to set external_executor_id to those queued ti
    • 300+ dag failed with killed externally (status: success) normally less than 10
  2. patch adopt_or_reset_orphaned_tasks, not to adopt orphaned ti
    • no dag failed !

I read the notes below , but still don’t understand this problems:

  1. why should we handle queued ti in celery and set this external id ?

The problem for us was that we had one dag that reach 32 parallelize runnable task ( 32 leaf tasks) which was the value of parameter parallelism. After this, the scheduler was not able to run (or queue) any task. Increasing this parameter solve the problem for us.

Hey Guys, Currently we are on the Airflow 1.14 version; We were getting a similar issue with our tasks going under up_for_retry state for hours. I went thru this thread & comments|inputs from various users on tweaking the poke_interval values; Our original poke_interval was set to 60 and changing the value to ~93 seconds resolved the issue with tasks getting into up_for_retry state ; This worked like a charm, but wanted to get more details on the race condition that scheduler is getting into when the poke_interval values are <= 60. Appreciate your help.

Trying Airflow 2.0.1. No tasks could be executed 😦

scheduler_1  | [2021-03-26 16:25:55,097] {{scheduler_job.py:941}} INFO - 1 tasks up for execution:

scheduler_1  |  <TaskInstance: test_dag.mirrors_to_vaniks 2021-03-26 16:25:55.009735+00:00 [scheduled]>

scheduler_1  | [2021-03-26 16:25:55,100] {{scheduler_job.py:975}} INFO - Figuring out tasks to run in Pool(name=default_pool) with 128 open slots and 1 task instances ready to be queued

scheduler_1  | [2021-03-26 16:25:55,100] {{scheduler_job.py:1002}} INFO - DAG test_dag has 0/16 running and queued tasks

scheduler_1  | [2021-03-26 16:25:55,100] {{scheduler_job.py:1063}} INFO - Setting the following tasks to queued state:

scheduler_1  |  <TaskInstance: test_dag.mirrors_to_vaniks 2021-03-26 16:25:55.009735+00:00 [scheduled]>

scheduler_1  | [2021-03-26 16:25:55,103] {{scheduler_job.py:1105}} INFO - Sending TaskInstanceKey(dag_id='test_dag', task_id='mirrors_to_vaniks', execution_date=datetime.datetime(2021, 3, 26, 16, 25, 55, 9735, tzinfo=Timezone('UTC')), try_number=1) to executor with priority 1 and queue default

scheduler_1  | [2021-03-26 16:25:55,104] {{base_executor.py:82}} INFO - Adding to queue: ['airflow', 'tasks', 'run', 'test_dag', 'mirrors_to_vaniks', '2021-03-26T16:25:55.009735+00:00', '--local', '--pool', 'default_pool', '--subdir', '/usr/local/airflow/dags/mwl/test_dag.py']

scheduler_1  | [2021-03-26 16:25:55,149] {{scheduler_job.py:1206}} INFO - Executor reports execution of test_dag.mirrors_to_vaniks execution_date=2021-03-26 16:25:55.009735+00:00 exited with status queued for try_number 1

scheduler_1  | [2021-03-26 16:25:55,154] {{scheduler_job.py:1226}} INFO - Setting external_id for <TaskInstance: test_dag.mirrors_to_vaniks 2021-03-26 16:25:55.009735+00:00 [queued]> to 53fa2dc3-9f17-4813-a1bc-7e28f18e0ddd

@turbaszek I just tried it again and I couldn’t replicate this error again on 2.0.

The cause is clear as @rafalkozik mentioned. After scheduler schedule the task at the second time(put it in queue) and then it start process the executor events of the task’s first-try. It occurs when the scheduling loop time > sensor task reschedule interval. Either reducing the scheduler looping time(dag processing time, etc) or increasing the sensor task reschedule interval will work.

The bug can also be fixed if the rescheduled task instance use a different try number, but this will cause a lot of log files.

    def _process_executor_events(self, simple_dag_bag, session=None):
       
       # ...
       
                if ti.try_number == try_number and ti.state == State.QUEUED:  # <-- try number for a sensor task is always the same
                    msg = ("Executor reports task instance {} finished ({}) "
                           "although the task says its {}. Was the task "
                           "killed externally?".format(ti, state, ti.state))
                    Stats.incr('scheduler.tasks.killed_externally')
                    self.log.error(msg)
                    try:
                        simple_dag = simple_dag_bag.get_dag(dag_id)
                        dagbag = models.DagBag(simple_dag.full_filepath)
                        dag = dagbag.get_dag(dag_id)
                        ti.task = dag.get_task(task_id)
                        ti.handle_failure(msg)
                    except Exception:
                        self.log.error("Cannot load the dag bag to handle failure for %s"
                                       ". Setting task to FAILED without callbacks or "
                                       "retries. Do you have enough resources?", ti)
                        ti.state = State.FAILED
                        session.merge(ti)
                        session.commit()

Ok @yuqian90 @sgrzemski-ias what is you setting for core.dagbag_import_timeout ?

As I’m hitting:

Traceback (most recent call last): File “/usr/local/lib/airflow/airflow/models/dagbag.py”, line 237, in process_file m = imp.load_source(mod_name, filepath) File “/opt/python3.6/lib/python3.6/imp.py”, line 172, in load_source module = _load(spec) File “”, line 684, in _load File “”, line 665, in _load_unlocked File “”, line 678, in exec_module File “”, line 219, in _call_with_frames_removed File “/home/airflow/gcs/dags/test_dag_1.py”, line 24, in time.sleep(30) File “/usr/local/lib/airflow/airflow/utils/timeout.py”, line 43, in handle_timeout raise AirflowTaskTimeout(self.error_message) airflow.exceptions.AirflowTaskTimeout: Timeout, PID: 6217

Hi, @turbaszek in my case I have dagbag_import_timeout = 100 and dag_file_processor_timeout = 300. Most of the time dag import takes about 10s. dag file processing can take 60s that’s why it’s set to a large number.

After digging further, I think the slowness that causes the error for our case is in this function: SchedulerJob._process_dags(). If this function takes around 60s, those reschedule sensors will hit the ERROR - Executor reports task instance ... killed externally? error. My previous comment about adding the time.sleep(30) is just one way to replicate this issue. Anything that causes _process_dags() to slow down should be able to replicate this error.

As it was reported in original issue and comments this behavior should be possible to reproduce in case of fast sensors in reschedule mode. That’s why I was trying to use many DAGs like this:

from random import choice
from airflow.utils.dates import days_ago
from airflow.sensors.base_sensor_operator import BaseSensorOperator
from airflow.operators.bash_operator import BashOperator
from airflow import DAG
import time


class TestSensor(BaseSensorOperator):
    def __init__(self, **kwargs):
        super().__init__(**kwargs)
        self.mode = "RESCHEDULE"

    def poke(self, context):
        time.sleep(5)
        return choice([True, False, False])


args = {"owner": "airflow", "start_date": days_ago(1)}


with DAG(
    dag_id="%s",
    is_paused_upon_creation=False,
    max_active_runs=100,
    default_args=args,
    schedule_interval="0 * * * *",
) as dag:
    start = BashOperator(task_id="start", bash_command="echo 42")
    end = BashOperator(task_id="end", bash_command="echo 42")
    for i in range(3):
        next = TestSensor(task_id=f"next_{i}")
        start >> next >> end

And I was also playing with airflow config settings as described in comments. Although I saw failing tasks there was no issue like this one or… eventually the log was missing?

I did some tests with external task sensor but also no results.