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(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() ---------- 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
