Kubernetes doubling logs

[romanzdk]

Apache Airflow version

2.7.2

What happened

KubernetesPodOperator doubles some of the logs. Example output:

[2023-10-18, 13:23:50 UTC] {pod_manager.py:351} WARNING - Pod not yet started: some-pod-name-j26p33vl
[2023-10-18, 13:23:51 UTC] {before.py:40} INFO - Starting call to '***.providers.cncf.kubernetes.utils.pod_manager.PodManager.fetch_container_logs.<locals>.consume_logs', this is the 1st time calling it.
...
[2023-10-18, 13:24:17 UTC] {pod_manager.py:437} INFO - [base] �[1;37m[1697635432.6957748][some-pod-name-j26p33vl][app-name-production][app-name][INFO] Some app log[0m
[2023-10-18, 13:24:17 UTC] {pod_manager.py:437} INFO - [base] �[1;37m[1697635457.1289246][some-pod-name-j26p33vl][app-name-production][app-name][INFO] Some more app log[0m
...
[2023-10-18, 13:24:18 UTC] {pod_manager.py:483} WARNING - Pod some-pod-name-j26p33vl log read interrupted but container base still running
[2023-10-18, 13:24:19 UTC] {before.py:40} INFO - Starting call to '***.providers.cncf.kubernetes.utils.pod_manager.PodManager.fetch_container_logs.<locals>.consume_logs', this is the 1st time calling it.
[2023-10-18, 13:24:19 UTC] {pod_manager.py:437} INFO - [base] �[1;37m[1697635432.6957748][some-pod-name-j26p33vl][app-name-production][app-name][INFO] Some app log[0m
[2023-10-18, 13:24:19 UTC] {pod_manager.py:437} INFO - [base] �[1;37m[1697635457.1289246][some-pod-name-j26p33vl][app-name-production][app-name][INFO] Some more app log[0m
[2023-10-18, 13:24:19 UTC] {pod_manager.py:582} INFO - Pod some-pod-name-j26p33vl has phase Running
[2023-10-18, 13:24:21 UTC] {pod.py:824} INFO - Deleting pod: some-pod-name-j26p33vl

What you think should happen instead

No double logs

How to reproduce

Airflow 2.7.2, Kubernetes provider 7.7.0, KubernetesPodOperator

Operating System

Debian GNU/Linux 10 (buster)

Versions of Apache Airflow Providers

apache-airflow-providers-amazon==8.7.1
apache-airflow-providers-cncf-kubernetes==7.7.0
apache-airflow-providers-common-sql==1.7.2
apache-airflow-providers-ftp==3.5.2
apache-airflow-providers-http==4.5.2
apache-airflow-providers-imap==3.3.2
apache-airflow-providers-postgres==5.6.1
apache-airflow-providers-slack==8.1.0
apache-airflow-providers-sqlite==3.4.3

Deployment

Other Docker-based deployment

Deployment details

On-premise kubernetes cluster, LocalExecutor (3 replicas), 10 parallelism

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

[jscheffl]

Thanks for the bug report. As I don't have a local K8s cluster to reproduce, can you tell us if you are using deferred mode or "normal" execution? Assuming you use a KubernetesPodOperator?
Is this always happening or in some occasions and randomly in different areas/lines in different runs?

Internal notes: Does this relate to #33500 ?

[romanzdk]

"Normal" mode (no deferred). Yes, using KubernetesPodOperator. So I checked several different DAGs but did not really find any similarities.. Sometimes it happened with short-lived tasks, sometimes with long ones. Also some tasks are completely alright - no double logs :(

[RNHTTR]

I've definitely seen some instances of double logging. Can you try upgrading apache-airflow-providers-cncf-kubernetes to the latest version (7.13.0)?

[github-actions]

This issue has been automatically marked as stale because it has been open for 14 days with no response from the author. It will be closed in next 7 days if no further activity occurs from the issue author.

[github-actions]

This issue has been closed because it has not received response from the issue author.