homepage

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.