Repository navigation
Wrong try_number after rescheduling makes remote logging store all the logs with wrong log_id #18080
Description
Apache Airflow version
2.1.3 (latest released)
Operating System
Debian GNU/Linux 10 (buster)
Versions of Apache Airflow Providers
apache-airflow-providers-elasticsearch==2.0.2
Deployment
Other Docker-based deployment
Deployment details
1 master node with webserver, scheduler, flower and etc.
4 worker node, each with a celery worker process;
filebeat 7.6.2 as sidecar reading logs with pattern /opt/airflow/logs/**/*.log from the official docker image container
What happened
I have set up filebeat and elasticsearch for remote logging and it works well with normal operator or tasks.
But when I tried ExternalTaskSensor with mode='reschedule' and poke_interval=300 option, the log view from the webpage showed something like the following.
...
[2021-09-08 15:10:03,392] {taskinstance.py:1094} INFO -
[2021-09-08 15:20:07,030] {taskinstance.py:1094} INFO -
[2021-09-08 15:15:04,941] {taskinstance.py:1094} INFO -
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
[2021-09-08 15:10:03,392] {taskinstance.py:1095} INFO - Starting attempt 1 of 4
[2021-09-08 15:20:07,030] {taskinstance.py:1095} INFO - Starting attempt 1 of 4
[2021-09-08 15:15:04,941] {taskinstance.py:1095} INFO - Starting attempt 1 of 4
[2021-09-08 15:20:07,030] {taskinstance.py:1096} INFO -
[2021-09-08 15:10:03,392] {taskinstance.py:1096} INFO -
[2021-09-08 15:15:04,941] {taskinstance.py:1096} INFO -
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
[2021-09-08 15:10:03,402] {taskinstance.py:1114} INFO - Executing <Task(ExternalTaskSensor):
[2021-09-08 15:20:07,041] {taskinstance.py:1114} INFO - Executing <Task(ExternalTaskSensor):
[2021-09-08 15:15:04,950] {taskinstance.py:1114} INFO - Executing <Task(ExternalTaskSensor):
...Apparently, the logs from different runs on different worker node, got pulled together, because they share the same try_number: 1, which means the log_id used to retrieve logs from remote storage are the same.
What you expected to happen
Option 1: Update or increase try_number after a task has been marked as up_for_reschedule, so that the log_id would be different by runs. This will probably solve some relevant issues from reschedule/try_number and log_id
Option 2: Fix the sensor mode, and do not use up_for_reschedule, maybe up_for_retry? But this would change the behaviors of all the sensor operator, seems like a big change
Option 3: Update the log location and its log_id, maybe include a reschedule_number besides the try_number, but this will need to change the log_id template, also seems like a big change
How to reproduce
Essential components
- filebeat and working elasticsearch cluster
- multiple worker nodes so that the logs with the same try_number may be created on different nodes
- Use ExternalTaskSensor with
mode='reschedule'to sense an upperstream task that needs multiple reschedules to succeed
Anything else
No response
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
boring-cyborg commentedon Sep 8, 2021
Thanks for opening your first issue here! Be sure to follow the issue template!
tanvn commentedon Nov 11, 2021
I got the same issue today with version 2.2.1 (the latest)
because the
try_numberis not changed when the task is marked asUP_FOR_SCHEDULE,my ExternalTaskSensor with a
retries = 3does not stop after 3 times andon_failure_callbacknever got called.(It ran until being marked as SUCCESS and the
on_success_callbackgot called).I think the cause is the below code.
https://github.com/apache/airflow/blob/main/airflow/models/taskinstance.py#L1673-L1678
And IMHO, 👍 + 1 for
uranusjr commentedon Nov 15, 2021
Does anyone happen to know if this is a recent regression? The
-= 1line referenced above is over three years old, so if this is a recent bug, it should likely be fixed elsewhere.potiuk commentedon Nov 17, 2021
I think it might be regression. I am not very confident in this part of the code, but I do remember, that somewhere in airlfow internals try_num was actually one higher that it should have been for some obscure reasons and it was manually decreased in some cases. So if the "obscurity" has been fixed in one of the recent refactors/fixes - this might be the side effect.
potiuk commentedon Nov 17, 2021
@ashb @mik-laj - maybe you remember better ?
ashb commentedon Nov 17, 2021
@ephraimbuddy ring any bells? I think we talked about this a while back
Is it fixed already do you know?
eladkal commentedon Nov 5, 2022
it's due to the difference between running task vs non running task see #26993 (comment)
github-actions commentedon Nov 6, 2023
This issue has been automatically marked as stale because it has been open for 365 days without any activity. There has been several Airflow releases since last activity on this issue. Kindly asking to recheck the report against latest Airflow version and let us know if the issue is reproducible. The issue will be closed in next 30 days if no further activity occurs from the issue author.
github-actions commentedon Dec 10, 2023
This issue has been closed because it has not received response from the issue author.