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 <1334930228.42.0.0482247289102.issue14632@psf.upfronthosting.co.za>
In-reply-to
Content
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.
History
Date User Action Args
2012-04-20 13:57:08phlogistonjohnsetrecipients: + phlogistonjohn
2012-04-20 13:57:08phlogistonjohnsetmessageid: <1334930228.42.0.0482247289102.issue14632@psf.upfronthosting.co.za>
2012-04-20 13:57:07phlogistonjohnlinkissue14632 messages
2012-04-20 13:57:07phlogistonjohncreate