New submission from Gleb Dubovik:
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(100):
... 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()
--
components: Library (Lib)
messages: 243804
nosy: dubglan
priority: normal
severity: normal
status: open
title: logging.FileHandler.close() is not thread-safe
type: behavior
versions: Python 2.7
___
Python tracker rep...@bugs.python.org
http://bugs.python.org/issue24262
___
___
Python-bugs-list mailing list
Unsubscribe:
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
