Message158829
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. |
|
Date |
User |
Action |
Args |
2012-04-20 13:57:08 | phlogistonjohn | set | recipients:
+ phlogistonjohn |
2012-04-20 13:57:08 | phlogistonjohn | set | messageid: <1334930228.42.0.0482247289102.issue14632@psf.upfronthosting.co.za> |
2012-04-20 13:57:07 | phlogistonjohn | link | issue14632 messages |
2012-04-20 13:57:07 | phlogistonjohn | create | |
|