scheduler logging bug in shouldRollover - "due to non-posix-compliant windows feature"

[ITJamie]

Apache Airflow version

2.2.3 (latest released)

What happened

Ive seen this bug in 2.1.4 and 2.2.3.

airflow-scheduler_1  | --- Logging error ---
airflow-scheduler_1  | Traceback (most recent call last):
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/logging/handlers.py", line 69, in emit
airflow-scheduler_1  |     if self.shouldRollover(record):
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/logging/handlers.py", line 186, in shouldRollover
airflow-scheduler_1  |     self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
airflow-scheduler_1  | ValueError: I/O operation on closed file.
airflow-scheduler_1  | Call stack:
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/bin/airflow", line 8, in <module>
airflow-scheduler_1  |     sys.exit(main())
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/__main__.py", line 48, in main
airflow-scheduler_1  |     args.func(args)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/cli_parser.py", line 48, in command
airflow-scheduler_1  |     return func(*args, **kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/utils/cli.py", line 92, in wrapper
airflow-scheduler_1  |     return f(*args, **kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/commands/scheduler_command.py", line 75, in scheduler
airflow-scheduler_1  |     _run_scheduler_job(args=args)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/commands/scheduler_command.py", line 46, in _run_scheduler_job
airflow-scheduler_1  |     job.run()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/jobs/base_job.py", line 245, in run
airflow-scheduler_1  |     self._execute()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/jobs/scheduler_job.py", line 624, in _execute
airflow-scheduler_1  |     self.processor_agent.start()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 161, in start
airflow-scheduler_1  |     process.start()
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/process.py", line 121, in start
airflow-scheduler_1  |     self._popen = self._Popen(self)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/context.py", line 277, in _Popen
airflow-scheduler_1  |     return Popen(process_obj)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/popen_fork.py", line 19, in __init__
airflow-scheduler_1  |     self._launch(process_obj)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/popen_fork.py", line 75, in _launch
airflow-scheduler_1  |     code = process_obj._bootstrap(parent_sentinel=child_r)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
airflow-scheduler_1  |     self.run()
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/process.py", line 108, in run
airflow-scheduler_1  |     self._target(*self._args, **self._kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 287, in _run_processor_manager
airflow-scheduler_1  |     processor_manager.start()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 520, in start
airflow-scheduler_1  |     return self._run_parsing_loop()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 585, in _run_parsing_loop
airflow-scheduler_1  |     self._find_zombies()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/utils/session.py", line 70, in wrapper
airflow-scheduler_1  |     return func(*args, session=session, **kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 1065, in _find_zombies
airflow-scheduler_1  |     self.log.info("Finding 'running' jobs without a recent heartbeat")
airflow-scheduler_1  | Message: "Finding 'running' jobs without a recent heartbeat"
airflow-scheduler_1  | Arguments: ()
airflow-scheduler_1  | --- Logging error ---
airflow-scheduler_1  | Traceback (most recent call last):
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/logging/handlers.py", line 69, in emit
airflow-scheduler_1  |     if self.shouldRollover(record):
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/logging/handlers.py", line 186, in shouldRollover
airflow-scheduler_1  |     self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
airflow-scheduler_1  | ValueError: I/O operation on closed file.
airflow-scheduler_1  | Call stack:
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/bin/airflow", line 8, in <module>
airflow-scheduler_1  |     sys.exit(main())
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/__main__.py", line 48, in main
airflow-scheduler_1  |     args.func(args)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/cli_parser.py", line 48, in command
airflow-scheduler_1  |     return func(*args, **kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/utils/cli.py", line 92, in wrapper
airflow-scheduler_1  |     return f(*args, **kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/commands/scheduler_command.py", line 75, in scheduler
airflow-scheduler_1  |     _run_scheduler_job(args=args)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/cli/commands/scheduler_command.py", line 46, in _run_scheduler_job
airflow-scheduler_1  |     job.run()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/jobs/base_job.py", line 245, in run
airflow-scheduler_1  |     self._execute()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/jobs/scheduler_job.py", line 624, in _execute
airflow-scheduler_1  |     self.processor_agent.start()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 161, in start
airflow-scheduler_1  |     process.start()
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/process.py", line 121, in start
airflow-scheduler_1  |     self._popen = self._Popen(self)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/context.py", line 277, in _Popen
airflow-scheduler_1  |     return Popen(process_obj)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/popen_fork.py", line 19, in __init__
airflow-scheduler_1  |     self._launch(process_obj)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/popen_fork.py", line 75, in _launch
airflow-scheduler_1  |     code = process_obj._bootstrap(parent_sentinel=child_r)
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
airflow-scheduler_1  |     self.run()
airflow-scheduler_1  |   File "/opt/bitnami/python/lib/python3.8/multiprocessing/process.py", line 108, in run
airflow-scheduler_1  |     self._target(*self._args, **self._kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 287, in _run_processor_manager
airflow-scheduler_1  |     processor_manager.start()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 520, in start
airflow-scheduler_1  |     return self._run_parsing_loop()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 585, in _run_parsing_loop
airflow-scheduler_1  |     self._find_zombies()
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/utils/session.py", line 70, in wrapper
airflow-scheduler_1  |     return func(*args, session=session, **kwargs)
airflow-scheduler_1  |   File "/opt/bitnami/airflow/venv/lib/python3.8/site-packages/airflow/dag_processing/manager.py", line 1069, in _find_zombies
airflow-scheduler_1  |     self.log.info("Failing jobs without heartbeat after %s", limit_dttm)
airflow-scheduler_1  | Message: 'Failing jobs without heartbeat after %s'
airflow-scheduler_1  | Arguments: (datetime.datetime(2022, 1, 17, 14, 32, 54, 539363, tzinfo=Timezone('UTC')),)

What you expected to happen

No response

How to reproduce

No response

Operating System

ubuntu 20.04 - docker ce - bitnami prebuilt images

Versions of Apache Airflow Providers

bitnami airflow container 2.2.3
from inside container

apache-airflow-providers-amazon==2.4.0
apache-airflow-providers-apache-cassandra==2.1.0
apache-airflow-providers-apache-drill==1.0.1
apache-airflow-providers-apache-druid==2.1.0
apache-airflow-providers-apache-hdfs==2.2.0
apache-airflow-providers-apache-hive==2.1.0
apache-airflow-providers-apache-pinot==2.0.1
apache-airflow-providers-celery==2.1.0
apache-airflow-providers-cloudant==2.0.1
apache-airflow-providers-cncf-kubernetes==2.2.0
apache-airflow-providers-docker==2.3.0
apache-airflow-providers-elasticsearch==2.1.0
apache-airflow-providers-exasol==2.0.1
apache-airflow-providers-ftp==2.0.1
apache-airflow-providers-google==6.2.0
apache-airflow-providers-grpc==2.0.1
apache-airflow-providers-hashicorp==2.1.1
apache-airflow-providers-http==2.0.1
apache-airflow-providers-imap==2.0.1
apache-airflow-providers-influxdb==1.1.0
apache-airflow-providers-microsoft-azure==3.4.0
apache-airflow-providers-microsoft-mssql==2.0.1
apache-airflow-providers-mongo==2.2.0
apache-airflow-providers-mysql==2.1.1
apache-airflow-providers-neo4j==2.0.2
apache-airflow-providers-postgres==2.4.0
apache-airflow-providers-presto==2.0.1
apache-airflow-providers-redis==2.0.1
apache-airflow-providers-sendgrid==2.0.1
apache-airflow-providers-sftp==2.3.0
apache-airflow-providers-slack==4.1.0
apache-airflow-providers-sqlite==2.0.1
apache-airflow-providers-ssh==2.3.0
apache-airflow-providers-trino==2.0.2
apache-airflow-providers-vertica==2.0.1

Deployment

Docker-Compose

Deployment details

bitnami airflow images. tested on 2.1.4 and 2.2.3.

docker-compose version 1.29.2, build 5becea4c
docker-py version: 5.0.0
CPython version: 3.7.10
OpenSSL version: OpenSSL 1.1.0l  10 Sep 2019

Client: Docker Engine - Community
 Version:           20.10.12
 API version:       1.41
 Go version:        go1.16.12
 Git commit:        e91ed57
 Built:             Mon Dec 13 11:45:33 2021
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.12
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.16.12
  Git commit:       459d0df
  Built:            Mon Dec 13 11:43:42 2021
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.12
  GitCommit:        7b11cfaabd73bb80907dd23182b9347b4245eb5d
 runc:
  Version:          1.0.2
  GitCommit:        v1.0.2-0-g52b36a2
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Anything else

every minute or so the error appears in airflow logs

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

[potiuk]

The message is quite clear - and this is your deployment problem, not Airflow.

You have non-compliant POSIX filesystem mounted for your logs (likely Windows-related). Airflow is only supposed to work with POSIX compliant systems (See the note in https://airflow.apache.org/docs/apache-airflow/stable/installation/prerequisites.html) and if you mount a non-POSIX compliant volume to the docker container, it will not work in some cases like this.

Change it to mount a POSIX-compliant filesystem there (but you need to figure out how to do it in your deployment as this is deployment-specific thing).

[ITJamie]

This is running 100% on linux though...
The container is running on a linux machine and all volume mounts are on linux hosts...

[potiuk]

This is running 100% on linux though... The container is running on a linux machine and all volume mounts are on linux hosts...

That was my guess - ther are similar to issues (if you google them) that this happens on Windows filesystem.

You need to check if all your volumes POSIX compliant. You should also take a close look how your logging is configured. Seems that the error really has nothing to do with Airflow - this is (possibly) BaseRotatingLogHandler which tries to do a filesystem operation on non-POSIX volume (apparently).

Airflow does not configure RotatingFileHandler so it's either your configuration or Bitnami image configuration - in neither case it's Airflow bug most likely. I will convert the issue to discussion - maybe other users had similar problems, but you should really try to investigate and understand your deployment.

[potiuk]

Also - If you want some help to diagnose the issue with the deployment you need to provide detailed information about your logging configuration - it looks like (maybe) one of your logging handlers is somewhat buggy/

[ryhorB-epam]

I have the same error, but the version is different
airflow 1.10.14
docker image based on debian buster

[potiuk]

Not helpful - this is likely wrong way of runnning airflow with mounted windows folder (which is likely not going to work). But this is deployment issue not Airflow issue and likely not version dependent.

BTW. Airlfow 1.10.14 is end-of-life as of June 2021 and will not receive any fixes (including critical security fixes). Upgrade ASAP.

[ITJamie]

For me this turned out to be interesting (forgot to update this thread when i finally found the issue)

Tldr: nfs4 doesnt support locking in the same way. If your underlying directory that logs goto is in an nfs share pin the nfs connection on client side to nfs3

So our setup is full linux environment. The vms that airflow ran on have /data as an nfs mount. Airflow had been working perfectly with this for quite some time. Our linux server which runs ubuntu was dist-upgraded. The newer os had nfs4 compatible server. Next time the normal client machine's rebooted or network restart the nfs mount came up over nfs4 instead of nfs3.

It was not at all obvious what had caused this issue as a setup that had been working for over a year stopped working and only on some of our airflow workers / schedulers.

I would really recommend catching this error in the airflow code and write the log entry line by line (the issue being that multiline logs in the logging module requires a lock which is then trying to make a posix lock which fails) OR at least output a more understandable error.

[potiuk]

Oh wow - very interesting one.

I would really recommend catching this error in the airflow code and write the log entry line by line (the issue being that multiline logs in the logging module requires a lock which is then trying to make a posix lock which fails) OR at least output a more understandable error.

Great idea! Since you have an environment about testing it - how about modifying it locally and provide a PR that handles it? That would be a nice contribution - Airflow has already almost 2000 contributors, and this could be a very nice contribution!

[potiuk]

And I think just outputting more understandable error will be much better, trying to write one-by-one will only mask the problem and will have likely huge performance penalty.

[lzf12]

How to deal with this problem, I also encountered it

[potiuk]

You need to check if all your volumes POSIX compliant. You should also take a close look how your logging is configured. Seems that the error really has nothing to do with Airflow - this is (possibly) BaseRotatingLogHandler which tries to do a filesystem operation on non-POSIX volume (apparently).