We're using FileHandler in combination with pytest plugin. Every time new test starts, new FileHandler is created and attached to the root logger, at the end of the test FileHandler is removed. This allows us to create per-test log files.
There are some threads that persist throughout the test session. They may perform logging at about the same time when we remove FileHandler.
Sometimes either thread that performs logging or the thread that closes the handler raise an exception:
ValueError: I/O operation on closed file
IOError: close() called during concurrent operation on the same file object.
AttributeError: 'NoneType' object has no attribute 'write'
Before closing the handler we do remove it from the logger.
This happens because operations that access FileHandler.stream (like close() and flush()) do not acquire the handler lock that guards emit() method. As a result, one thread may start closing the stream while the other freely enters emit and tries to write to the file. The race may happen within the file object and on the stream field itself (the combination "if stream is not None: stream = None" is not thread-safe).
This issue is related to two other bugs:
https://bugs.python.org/issue1760556
https://bugs.python.org/issue11444
Repro code:
Python 2.7.3 (default, Feb 27 2014, 19:58:35)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import threading
>>> import time
>>> import logging
>>>
>>> root_logger = logging.getLogger()
>>> root_logger.addHandler(logging.NullHandler())
>>>
>>> def do_logging():
... for _ in xrange(1000000):
... logging.error("TEST!"*100)
...
>>> threading.Thread(target=do_logging).start()
>>>
>>> for _ in xrange(100):
... handler = logging.FileHandler("/tmp/test")
... root_logger.addHandler(handler)
... time.sleep(6)
... root_logger.removeHandler(handler)
... handler.close()
...
Traceback (most recent call last):
File "/usr/lib/python2.7/logging/__init__.py", line 867, in emit
stream.write(fs % msg)
AttributeError: 'NoneType' object has no attribute 'write'
Logged from file <stdin>, line 3
Traceback (most recent call last):
File "<stdin>", line 6, in <module>
File "/usr/lib/python2.7/logging/__init__.py", line 906, in close
self.stream.close()
IOError: close() called during concurrent operation on the same file object.
>>> exit()
|
➜
