RotatingFileHandler gives ValueError: I/O operation on closed file

[codeape]

My application starts to throw ValueError when it rotates files:

2015-03-04 07:47:00.177000 Test request
Traceback (most recent call last):
  File "C:\Python27\lib\site-packages\logbook\handlers.py", line 217, in handle
    self.emit(record)
  File "C:\Python27\lib\site-packages\logbook\handlers.py", line 753, in emit
    if self.should_rollover(record, len(msg)):
  File "C:\Python27\lib\site-packages\logbook\handlers.py", line 731, in should_
rollover
    self.stream.seek(0, 2)
ValueError: I/O operation on closed file
Logged from file C:\Users\monkey.whiteshark\spawn\spawn-git\spawnlib\servant\mai
n.py, line 778
2015-03-04 07:47:00.180000 Reply    msg 16067 with type 'testing'

After this there is no return, the file will not rotate and these messages keep on showing up.

My application only uses gevent greenlets and I do not use ordinary threads anywhere. This is the start script of my application.

#!/usr/bin/python
# -*- coding: utf-8 -*-

import gevent.monkey
gevent.monkey.patch_all()

from logbook.concurrency import enable_gevent, is_gevent_enabled
enable_gevent()
assert is_gevent_enabled()

from logbook import NestedSetup, NullHandler, RotatingFileHandler, StreamHandler
from spawnlib.common.configurator import ConfiguratorFormatException
from spawnlib.servant import main as servant_main
import logbook
import logbook.concurrency
import os
import sys
import traceback


def main():
    """Handle collecting and checking all configuration for the servant and starts the servant loop."""
    config_path = os.path.dirname(os.path.realpath(__file__))
    cfger = servant_main.configurator()
    cfg_path = os.path.normpath(os.path.join(config_path, 'spawn_servant.json'))
    try:
        cfg = cfger.load_file(cfg_path)
    except ConfiguratorFormatException as e:
        # We need to use print before we init our logger, otherwise we will get a logger that is broken.
        print e.message
        sys.exit(1)
    log_file_path = os.path.join(cfg[servant_main.ARG_LOG_FILE], 'spawn-servant.log')
    if not os.path.isdir(cfg[servant_main.ARG_LOG_FILE]):
        # We need to use print before we init our logger, otherwise we will get a logger that is broken.
        print "Path not a directory: {}".format(cfg[servant_main.ARG_LOG_FILE])
        sys.exit(1)
    # Lets start logbook
    log_level = logbook.INFO
    if cfg.get(servant_main.ARG_DEBUG):
        log_level = logbook.DEBUG
    logbook.set_datetime_format("local")
    stream_logger = StreamHandler(sys.stdout, level=log_level, encoding='utf-8')
    stream_logger.format_string = '{record.time} {record.message}'
    file_logger = RotatingFileHandler(log_file_path, level=log_level, encoding='utf-8', max_size=5000000, backup_count=10, bubble=True)
    file_logger.format_string = '{record.time};{record.level_name};{record.message}'
    nested = NestedSetup([NullHandler(), stream_logger, file_logger])
    nested.push_application()
    # Check configuration
    # Check that we run enough monitors
    if cfg[servant_main.ARG_MAX_MONITORS] < 1:
        logbook.error("The minimum number of monitors is 1")
        sys.exit(1)
    # Start waiting for something to do
    try:
        servant_main.loop(cfg)
    except:
        logbook.error(traceback.format_exc())
        raise
    finally:
        nested.pop_application()

if __name__ == '__main__':
    main()

[codeape]

It looks like this only happens on Windows machines and never Linux machines.

<--- Insert Windows rant here.

[RazerM]

Can you provide a minimally working example, so I can try to reproduce? I assume spawnlib is your own module.

[simpleseeker]

I'm running into this issue on CentOS 6.6:

ValueError: I/O operation on closed file
Traceback (most recent call last):
File "/usr/lib64/python2.6/logging/handlers.py", line 76, in emit
if self.shouldRollover(record):
File "/usr/lib64/python2.6/logging/handlers.py", line 150, in shouldRollover
self.stream.seek(0, 2) #due to non-posix-compliant Windows feature

[brainstorm]

Good point @RazerM: @simpleseeker, @codeape could any of you provide a minimal example of that so that we can write a test about it?

[vikram-narayan]

I ran into this on ubuntu as well.

[brainstorm]

@vikram-narayan, can you paste/point us to a small example, please?

[veaviticus]

I've managed to produce a minimal flask app that recreates this
https://gist.github.com/veaviticus/fb1ad2606decd65a209b

Looks like if the log is already full and you try to write to it, it attempts to rotate the file and fails first due to a permission error in windows (see the Output.txt file in the gist), then every subsequent attempt fails with "I/O operation on closed file"

[RazerM]

Thanks @veaviticus, I wonder if this is related to how Flask's auto-reloading works.

Edit: Yeah it only happens when debug=True

[veaviticus]

That would explain why I've only seen on my local machine and not in the production app using logbook yet. And as long as you don't leave the log around forever when debugging, it's not really a huge issue

[AndreiPashkin]

Confirming the same problem on Linux:

Traceback (most recent call last):
  File "/app/env/local/lib/python2.7/site-packages/logbook/handlers.py", line 213, in handle
    self.emit(record)
  File "/app/env/local/lib/python2.7/site-packages/logbook/handlers.py", line 762, in emit
    self.perform_rollover()
  File "/app/env/local/lib/python2.7/site-packages/logbook/handlers.py", line 753, in perform_rollover
    rename(self._filename, self._filename + '.1')
OSError: [Errno 16] Device or resource busy
Logged from file /app/env/local/lib/python2.7/site-packages/celery/bootsteps.py, line 272
[2019-04-08 21:29:20.668674] DEBUG: celery.bootsteps: | Worker: Building graph...
Traceback (most recent call last):
  File "/app/env/local/lib/python2.7/site-packages/logbook/handlers.py", line 213, in handle
    self.emit(record)
  File "/app/env/local/lib/python2.7/site-packages/logbook/handlers.py", line 761, in emit
    if self.should_rollover(record, len(msg)):
  File "/app/env/local/lib/python2.7/site-packages/logbook/handlers.py", line 739, in should_rollover
    self.stream.seek(0, 2)
ValueError: I/O operation on closed file.

It seems like perform_rollover() closes the stream and in subsequent invocation of the handler should_rollover() tries to operate on the same stream again but it's already closed.

[visch]

Hit this on Windows, running with dbt. Had a large number of threads (14), and I believe the log directory is over the network

  File "e:\app\.dbtvenv\lib\site-packages\logbook\handlers.py", line 840, in emit
    if self.should_rollover(record, len(msg)):
Traceback (most recent call last):
  File "e:\app\.dbtvenv\lib\site-packages\dbt\logger.py", line 458, in emit
    super().emit(record)
Logged from file e:\app\.dbtvenv\lib\site-packages\dbt\contracts\results.py, line 57
Traceback (most recent call last):
Logged from file e:\app\.dbtvenv\lib\site-packages\dbt\adapters\sqlserver\connections.py, line 353
  File "e:\app\.dbtvenv\lib\site-packages\logbook\handlers.py", line 216, in handle
    self.emit(record)
Logged from file e:\app\.dbtvenv\lib\site-packages\dbt\contracts\results.py, line 57
  File "e:\app\.dbtvenv\lib\site-packages\logbook\handlers.py", line 818, in should_rollover
    self.stream.seek(0, 2)
  File "e:\app\.dbtvenv\lib\site-packages\logbook\handlers.py", line 840, in emit
    if self.should_rollover(record, len(msg)):
Traceback (most recent call last):
  File "e:\app\.dbtvenv\lib\site-packages\logbook\handlers.py", line 216, in handle
    self.emit(record)

Potentially related to dbt-labs/dbt-core#3399