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.

Title: logging.FileHandler.close() is not thread-safe
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 2.7
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: dubglan, vinay.sajip
Priority: normal Keywords:

Created on 2015-05-22 04:12 by dubglan, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Messages (2)
msg243804 - (view) Author: Gleb Dubovik (dubglan) Date: 2015-05-22 04:12
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 (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:

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/", 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/", line 906, in close
IOError: close() called during concurrent operation on the same file object.
>>> exit()
msg243810 - (view) Author: Gleb Dubovik (dubglan) Date: 2015-05-22 06:33
We used a very old version of python shipped with 12.04 LTS. The bug was fixed in 2.7.3 in 2ab3a97d544c by Vinay.
Date User Action Args
2022-04-11 14:58:17adminsetgithub: 68450
2015-05-22 13:46:52r.david.murraysetresolution: fixed -> out of date
stage: resolved
2015-05-22 06:33:48dubglansetstatus: open -> closed
resolution: fixed
messages: + msg243810
2015-05-22 06:27:57ned.deilysetnosy: + vinay.sajip
2015-05-22 04:12:29dubglancreate