You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by GitBox <gi...@apache.org> on 2021/07/26 19:40:21 UTC
[GitHub] [airflow] mgorsk1 opened a new issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
mgorsk1 opened a new issue #17238:
URL: https://github.com/apache/airflow/issues/17238
**Apache Airflow version**:
**2.1.2**
**Kubernetes version (if you are using kubernetes)** (use `kubectl version`):
**v1.19.4**
**Environment**:
- **Cloud provider or hardware configuration**: self-hosted k8s
- **OS** (e.g. from /etc/os-release):
- **Kernel** (e.g. `uname -a`):
- **Install tools**:
- **Others**: **KubernetesExecutor**
**What happened**:
We are running DAG on k8s using DummyOperator, PythonOperator and KubernetesPodOperator.
From time to time random tasks in the DAG are marked as `skipped` although we are not raising AirflowSkipException in our code and all previous tasks finished successfully:
From the UI it looks like the task was not run at all (and there are no task execution logs in UI) it actually seems that the task pod (worker) was executed and finished. We are able to find in Airflow scheduler logs what was the unique pod name for the `end` task and logs proving that it has completed ok. Additionally our k8s monitoring says that the pod of the same name indeed existed within the namespace at the exact time Airflow logs say it was spawned.
The situation occurs for every type of operator (so it's not only for DummyOperator used for `end` task).
It also makes whole DAG Run land in `failed` state.
**What you expected to happen**:
Both task instance and DAG run are `success`
**How to reproduce it**:
It occurs randomly and we are not sure how to reproduce it. It seems that it occurs more often if there are a lot of DAGs/tasks running in Airflow at once (although we limit task parallelism to 16 per DAG and 32 per whole Airflow instance).
**Anything else we need to know**:
What's also interesting is that it almost every time happens to whole group of tasks.
Below diagram shows rendered DAG and 3 situations of equal probability of happening (green box is task=success and pink box is task=skipped). TG1 TG2 TG3 are identifiers for different operators used (either python or kubernetespodoperator):
How often does this problem occur? Once? Every time etc?
It occurs randomly - one day the same DAG is ok, the other way it suffers from this issue.
Any relevant logs to include? Put them here in side a detail tag:
Above log shows that Airflow actually executed worker pod with task and it succeeded, but status of the task in UI claims otherwise:
-->
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889938062
I noticed it is more likely to happen when there are a lot of DAGs triggered at the same time. We trigger DAGs with external app and today around 10 DAGs were executed within 3 minutes window. All of them failed and most of them were affected by this bug.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-895140926
Ok I think we've more-less figured what was the reason. I am curious to know what do you think about our findings:
1. We had a DAGs code containing `dagrun_timeout=timedelta(minutes=60)`. This code was running on prod for 2 years with Airflow `1.10+`
2. According to docs (https://airflow.apache.org/docs/apache-airflow/stable/_api/airflow/models/index.html) this configuration option should not take effect if DAG has `schedule=None` which was the case for all of our DAGs (so despite it was in the code, regardless of the intention, it should not be used by Airflow).
```
dagrun_timeout (datetime.timedelta) – specify how long a DagRun should be up before timing out / failing, so that new DagRuns can be created. **The timeout is only enforced for scheduled DagRuns.**
```
3. After migrating to Airflow 2 our DAGs, which previously took more than 1 hour has noted significant improvement in DAG run so it became highly unlikely to reach 60 minutes of a timeout, but whenever it happened indeed the tasks were marked as skipped or failed.
Below code shows this inconsistency between docs and actual behavior (timeout should not happened but actually tasks are killed mid-run, marked as skipped and subsequently as failed):
```
import time
from datetime import datetime, timedelta
from airflow import DAG
from airflow.operators.dummy import DummyOperator
from airflow.operators.python import PythonOperator
default_args = {"start_date": datetime(2021, 7, 30)}
with DAG("dagrun_timeout_error", default_args=default_args,
schedule_interval=None,
dagrun_timeout=timedelta(seconds=60)) as dag:
start = DummyOperator(task_id="start")
end = DummyOperator(task_id="end")
for i in range(5):
prev = start
for j in range(3):
t = PythonOperator(
task_id=f"t-{i}-{j}", python_callable=lambda: time.sleep(120)
)
prev >> t
prev = t
t >> end
```
So I understand it's either change of behavior that wasn't documented properly or it's a bug with undesired behavior. Let me know WDYT.
Thanks to @dechoma for debugging this together.
cc @jedcunningham @ephraimbuddy
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889000426
Thanks for clarifing @jedcunningham completely agree, that log refers to pod state. But are there any scenarios if the task goes into `skipped` mode at all? From the docs I only saw this possible if we are explicitly raising AirflowSkipException in the task.
Although since task is in `skipped` phase in UI so the logs are not retrievable from UI, I found them on our S3 and this is what they say @ephraimbuddy:
We are running single scheduler. Sometimes when I look into the NS where Airflow resides I see that some task pods are failing with following logs (but not sure if it's related):
which is werid cause the corresponding task in Airflow UI is marked as success (without retrying) and I can see logs from both Airflow worker and Kubernetes pod that was executed by it. Kubernetes monitoring shows that such pod indeed existed which makes the 404 more weird as I would only expect some race condition with 2+ schedulers, not single one.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] jedcunningham commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
jedcunningham commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-895333671
Nice fine. I lean toward not documented properly. Would you like to open a PR to fix that description?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] jedcunningham commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
jedcunningham commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-888593645
Just to clarify, the `Event: {pod_name} Succeeded` line is referring to the the pod state, not the task state, so those won't always match.
Can you see if it also happens with [[scheduler] schedule_after_task_execution](https://airflow.apache.org/docs/apache-airflow/stable/configurations-ref.html#schedule-after-task-execution) set to `False`?
Are you running a single scheduler?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] jedcunningham commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
jedcunningham commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-890121751
I've tried to replicate this with the following DAG without success:
```
import time
from datetime import datetime
from airflow import DAG
from airflow.operators.dummy import DummyOperator
from airflow.operators.python import PythonOperator
default_args = {"start_date": datetime(2021, 7, 30)}
with DAG("skipped", default_args=default_args, schedule_interval=None) as dag:
start = DummyOperator(task_id="start")
end = DummyOperator(task_id="end")
for i in range(5):
prev = start
for j in range(3):
t = PythonOperator(
task_id=f"t-{i}-{j}", python_callable=lambda: time.sleep(10)
)
prev >> t
prev = t
t >> end
```
@mgorsk1, any chance you could try in your instance with that DAG? Also, filtering down to the pod name might be missing an important log message. I'd try filtering by a unique task_id (if there is one) too.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-895140926
Ok I think we've more-less figured what was the reason. I am curious to know what do you think about our findings:
1. We had a DAGs code containing `dagrun_timeout=timedelta(minutes=60)`. This code was running on prod for 2 years with Airflow `1.10+`
2. According to docs (https://airflow.apache.org/docs/apache-airflow/stable/_api/airflow/models/index.html) this configuration option should not take effect if DAG has `schedule=None` which was the case for all of our DAGs (so despite it was in the code, regardless of the intention, it should not be used by Airflow).
```
dagrun_timeout (datetime.timedelta) – specify how long a DagRun should be up before timing out / failing, so that new DagRuns can be created. **The timeout is only enforced for scheduled DagRuns.**
```
3. After migrating to Airflow 2 our DAGs, which previously took more than 1 hour has noted significant improvement in DAG run so it became highly unlikely to reach 60 minutes of a timeout, but whenever it happened indeed the tasks were marked as skipped and subsequently as failed.
Below code shows this inconsistency between docs and actual behavior (timeout should not happened but actually tasks are killed mid-run, ):
```
import time
from datetime import datetime, timedelta
from airflow import DAG
from airflow.operators.dummy import DummyOperator
from airflow.operators.python import PythonOperator
default_args = {"start_date": datetime(2021, 7, 30)}
with DAG("dagrun_timeout_error", default_args=default_args,
schedule_interval=None,
dagrun_timeout=timedelta(seconds=60)) as dag:
start = DummyOperator(task_id="start")
end = DummyOperator(task_id="end")
for i in range(5):
prev = start
for j in range(3):
t = PythonOperator(
task_id=f"t-{i}-{j}", python_callable=lambda: time.sleep(120)
)
prev >> t
prev = t
t >> end
```
So I understand it's either change of behavior that wasn't documented properly or it's a bug with undesired behavior. Let me know WDYT.
Thanks to @dechoma for debugging this together.
cc @jedcunningham @ephraimbuddy
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-895140926
Ok I think we've more-less figured what was the reason. I am curious to know what do you think about our findings:
1. We had a DAGs code containing `dagrun_timeout=timedelta(minutes=60)`. This code was running on prod for 2 years with Airflow `1.10+`
2. According to docs (https://airflow.apache.org/docs/apache-airflow/stable/_api/airflow/models/index.html) this configuration option should not take effect if DAG has `schedule=None` which was the case for all of our DAGs (so despite it was in the code, regardless of the intention, it should not be used by Airflow).
```
dagrun_timeout (datetime.timedelta) – specify how long a DagRun should be up before timing out / failing, so that new DagRuns can be created. **The timeout is only enforced for scheduled DagRuns.**
```
3. After migrating to Airflow 2 our DAGs, which previously took more than 1 hour has noted significant improvement in DAG run so it became highly unlikely to reach 60 minutes of a timeout, but whenever it happened indeed the tasks were marked as skipped or failed.
Below code shows this inconsistency between docs and actual behavior (timeout should not happened but actually tasks are killed mid-run, marked as skipped and subsequently as failed):
```
import time
from datetime import datetime, timedelta
from airflow import DAG
from airflow.operators.dummy import DummyOperator
from airflow.operators.python import PythonOperator
default_args = {"start_date": datetime(2021, 7, 30)}
with DAG("dagrun_timeout_error", default_args=default_args,
schedule_interval=None,
dagrun_timeout=timedelta(seconds=60)) as dag:
start = DummyOperator(task_id="start")
end = DummyOperator(task_id="end")
for i in range(5):
prev = start
for j in range(3):
t = PythonOperator(
task_id=f"t-{i}-{j}", python_callable=lambda: time.sleep(120)
)
prev >> t
prev = t
t >> end
```
So I understand it's either change of behavior that wasn't documented properly or it's a bug with undesired behavior. Let me know WDYT.
Thanks to @dechoma for debugging this together.
cc @jedcunningham @ephraimbuddy
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889938062
I noticed it is more likely to happen when there are a lot of DAGs triggered at the same time. We trigger DAGs with external app and today around 10 DAGs were executed within 3 minutes window. All of them failed and were affected by this bug.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889938062
I noticed it is more likely to happen when there are a lot of DAGs triggered at the same time. We trigger DAGs with external app and today around 7 DAGs were executed within 3 minutes window. All of them failed and were affected by this bug.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] jedcunningham edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
jedcunningham edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-895333671
Nice find. I lean toward not documented properly. Would you like to open a PR to fix that description?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889357393
it ends with:
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889355842
We're already logging with DEBUG so these are following lines re this DAG execution:
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] jedcunningham commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
jedcunningham commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889237766
The only other way I can think of off the top of my head is [exit code 99 with BashOperator](https://github.com/apache/airflow/blob/d7a68569a93d47040efdaf398cec01d682653a3f/airflow/operators/bash.py#L49-L51), but that clearly isn't the case here.
Maybe kick your logging level to DEBUG and see if anything helpful is in the scheduler log.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] ephraimbuddy commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
ephraimbuddy commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-888518650
I think you should get the scheduler log when this happens as well as the task log?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 edited a comment on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 edited a comment on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-889000426
Thanks for clarifing @jedcunningham completely agree, that log refers to pod state. But are there any scenarios if the task goes into `skipped` mode at all? From the docs I only saw this possible if we are explicitly raising AirflowSkipException in the task.
Although since task is in `skipped` phase in UI so the logs are not retrievable from UI, I found them on our S3 and this is what they say @ephraimbuddy:
**We are running single scheduler**.
Sometimes when I look into the NS where Airflow resides I see that some task pods are failing with following logs (but not sure if it's related):
which is werid cause the corresponding task in Airflow UI is marked as success (without retrying) and I can see logs from both Airflow worker and Kubernetes pod that was executed by it. Kubernetes monitoring shows that such pod indeed existed which makes the 404 more weird as I would only expect some race condition with 2+ schedulers, not single one.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [airflow] mgorsk1 commented on issue #17238: Unexpected skipped state for tasks run with KubernetesExecutor
Posted by GitBox <gi...@apache.org>.
mgorsk1 commented on issue #17238:
URL: https://github.com/apache/airflow/issues/17238#issuecomment-895140926
Ok I think we've more-less figured what was the reason. I am curious to know what do you think about our findings:
1. We had a DAGs code containing `dagrun_timeout=timedelta(minutes=60)`. This code was running on prod for 2 years with Airflow `1.10+`
2. According to docs (https://airflow.apache.org/docs/apache-airflow/stable/_api/airflow/models/index.html) this configuration option should not take effect if DAG has `schedule=None` which was the case for all of our DAGs.
```
dagrun_timeout (datetime.timedelta) – specify how long a DagRun should be up before timing out / failing, so that new DagRuns can be created. **The timeout is only enforced for scheduled DagRuns.**
```
3. After migrating to Airflow 2 our DAGs, which previously took more than 1 hour has noted significant improvement in DAG run so it became highly unlikely to reach 60 minutes of a timeout, but whenever it happened indeed the tasks were marked as skipped and subsequently as failed.
Below code shows this inconsistency between docs and actual behavior (timeout should not happened but actually tasks are killed mid-run, ):
```
import time
from datetime import datetime, timedelta
from airflow import DAG
from airflow.operators.dummy import DummyOperator
from airflow.operators.python import PythonOperator
default_args = {"start_date": datetime(2021, 7, 30)}
with DAG("dagrun_timeout_error", default_args=default_args,
schedule_interval=None,
dagrun_timeout=timedelta(seconds=60)) as dag:
start = DummyOperator(task_id="start")
end = DummyOperator(task_id="end")
for i in range(5):
prev = start
for j in range(3):
t = PythonOperator(
task_id=f"t-{i}-{j}", python_callable=lambda: time.sleep(120)
)
prev >> t
prev = t
t >> end
```
So I understand it's either change of behavior that wasn't documented properly or it's a bug with undesired behavior. Let me know WDYT.
Thanks to @dechoma for debugging this together.
cc @jedcunningham @ephraimbuddy
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org