New submission from JohnM <phlogistonj...@asynchrono.us>:
The (very handy) logging.handlers.WatchedFileHandler appears to be susceptible
to a race condition that causes occasional OSErrors during the normal course of
operations:
Traceback (most recent call last):
File "test.py", line 58, in test_race
log.warning('Foo bar %d', ii)
File "/usr/lib64/python2.7/logging/__init__.py", line 1144, in warning
self._log(WARNING, msg, args, **kwargs)
File "/usr/lib64/python2.7/logging/__init__.py", line 1250, in _log
self.handle(record)
File "/usr/lib64/python2.7/logging/__init__.py", line 1260, in handle
self.callHandlers(record)
File "/usr/lib64/python2.7/logging/__init__.py", line 1300, in callHandlers
hdlr.handle(record)
File "/usr/lib64/python2.7/logging/__init__.py", line 744, in handle
self.emit(record)
File "/usr/lib64/python2.7/logging/handlers.py", line 412, in emit
stat = os.stat(self.baseFilename)
OSError: [Errno 2] No such file or directory:
'/tmp/tmpG6_luRTestRaceWatchedFileHandler'
Looking at the implementation of the handler's emit function, I've commented on
where I think the race can occur. Logrotate (or some similar application) is
deleting/unlinking the logfile between the first os.path.exists and os.stat
calls:
def emit(self, record):
"""
Emit a record.
First check if the underlying file has changed, and if it
has, close the old stream and reopen the file to get the
current stream.
"""
if not os.path.exists(self.baseFilename):
# ^^^ race occurs between here
stat = None
changed = 1
else:
stat = os.stat(self.baseFilename)
# ^^^ and this stat call
changed = (stat[ST_DEV] != self.dev) or (stat[ST_INO] != self.ino)
if changed and self.stream is not None:
self.stream.flush()
self.stream.close()
self.stream = self._open()
if stat is None:
stat = os.stat(self.baseFilename)
self.dev, self.ino = stat[ST_DEV], stat[ST_INO]
logging.FileHandler.emit(self, record)
I've attached a test script that attempts to recreate the issue. On my Linux
system running the script is able to trigger the issue about every 7 of 10 runs.
----------
components: Library (Lib)
files: test.py
messages: 158829
nosy: phlogistonjohn
priority: normal
severity: normal
status: open
title: Race condition in WatchedFileHandler leads to unhandled exception
type: behavior
versions: Python 2.7
Added file: http://bugs.python.org/file25289/test.py
_______________________________________
Python tracker <rep...@bugs.python.org>
<http://bugs.python.org/issue14632>
_______________________________________
_______________________________________________
Python-bugs-list mailing list
Unsubscribe:
http://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
