This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

Author phlogistonjohn
Recipients phlogistonjohn
Date 2012-04-20.13:57:07
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <>
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 "", line 58, in test_race
    log.warning('Foo bar %d', ii)
  File "/usr/lib64/python2.7/logging/", line 1144, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/usr/lib64/python2.7/logging/", line 1250, in _log
  File "/usr/lib64/python2.7/logging/", line 1260, in handle
  File "/usr/lib64/python2.7/logging/", line 1300, in callHandlers
  File "/usr/lib64/python2.7/logging/", line 744, in handle
  File "/usr/lib64/python2.7/logging/", 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
            stat = os.stat(self.baseFilename)
            #      ^^^ and this stat call
            changed = (stat[ST_DEV] != or (stat[ST_INO] != self.ino)
        if changed and is not None:
   = self._open()
            if stat is None:
                stat = os.stat(self.baseFilename)
  , 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:08phlogistonjohnsetrecipients: + phlogistonjohn
2012-04-20 13:57:08phlogistonjohnsetmessageid: <>
2012-04-20 13:57:07phlogistonjohnlinkissue14632 messages
2012-04-20 13:57:07phlogistonjohncreate