This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

Author dubglan
Recipients dubglan
Date 2015-05-22.04:12:27
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1432267949.32.0.854494072121.issue24262@psf.upfronthosting.co.za>
In-reply-to
Content
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()
History
Date User Action Args
2015-05-22 04:12:29dubglansetrecipients: + dubglan
2015-05-22 04:12:29dubglansetmessageid: <1432267949.32.0.854494072121.issue24262@psf.upfronthosting.co.za>
2015-05-22 04:12:29dubglanlinkissue24262 messages
2015-05-22 04:12:27dubglancreate