Issue #14632: Updated WatchedFileHandler to deal with race condition. Thanks to John Mulligan for the problem report and patch.

2 files changed, 72 insertions, 23 deletions

diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py
index 65b0a2d..22f8c34 100644
--- a/Lib/logging/handlers.py
+++ b/Lib/logging/handlers.py
@@ -23,7 +23,7 @@ Copyright (C) 2001-2012 Vinay Sajip. All Rights Reserved.
 To use, simply 'import logging.handlers' and log away!
 """
 
-import logging, socket, os, pickle, struct, time, re
+import errno, logging, socket, os, pickle, struct, time, re
 from stat import ST_DEV, ST_INO, ST_MTIME
 import queue
 try:
@@ -383,11 +383,13 @@ class WatchedFileHandler(logging.FileHandler):
     """
     def __init__(self, filename, mode='a', encoding=None, delay=0):
         logging.FileHandler.__init__(self, filename, mode, encoding, delay)
-        if not os.path.exists(self.baseFilename):
-            self.dev, self.ino = -1, -1
-        else:
-            stat = os.stat(self.baseFilename)
-            self.dev, self.ino = stat[ST_DEV], stat[ST_INO]
+        self.dev, self.ino = -1, -1
+        self._statstream()
+
+    def _statstream(self):
+        if self.stream:
+            sres = os.fstat(self.stream.fileno())
+            self.dev, self.ino = sres[ST_DEV], sres[ST_INO]
 
     def emit(self, record):
         """
@@ -397,21 +399,30 @@ class WatchedFileHandler(logging.FileHandler):
         has, close the old stream and reopen the file to get the
         current stream.
         """
-        if not os.path.exists(self.baseFilename):
-            stat = None
-            changed = 1
-        else:
-            stat = os.stat(self.baseFilename)
-            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]
+        # Reduce the chance of race conditions by stat'ing by path only
+        # once and then fstat'ing our new fd if we opened a new log stream.
+        # See issue #14632: Thanks to John Mulligan for the problem report
+        # and patch.
+        try:
+            # stat the file by path, checking for existence
+            sres = os.stat(self.baseFilename)
+        except OSError as err:
+            if err.errno == errno.ENOENT:
+                sres = None
+            else:
+                raise
+        # compare file system stat with that of our stream file handle
+        if not sres or sres[ST_DEV] != self.dev or sres[ST_INO] != self.ino:
+            if self.stream is not None:
+                # we have an open file handle, clean it up
+                self.stream.flush()
+                self.stream.close()
+                # open a new file handle and get new stat info from that fd
+                self.stream = self._open()
+                self._statstream()
         logging.FileHandler.emit(self, record)
 
+
 class SocketHandler(logging.Handler):
     """
     A handler class which writes logging records, in pickle format, to
diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index ab66596..ca4d930 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -1,6 +1,6 @@
 #!/usr/bin/env python
 #
-# Copyright 2001-2011 by Vinay Sajip. All Rights Reserved.
+# Copyright 2001-2012 by Vinay Sajip. All Rights Reserved.
 #
 # Permission to use, copy, modify, and distribute this software and its
 # documentation for any purpose and without fee is hereby granted,
@@ -18,7 +18,7 @@
 
 """Test harness for the logging module. Run all tests.
 
-Copyright (C) 2001-2011 Vinay Sajip. All Rights Reserved.
+Copyright (C) 2001-2012 Vinay Sajip. All Rights Reserved.
 """
 
 import logging
@@ -33,6 +33,7 @@ import gc
 import json
 import os
 import queue
+import random
 import re
 import select
 import socket
@@ -43,6 +44,7 @@ import tempfile
 from test.support import captured_stdout, run_with_locale, run_unittest
 from test.support import TestHandler, Matcher
 import textwrap
+import time
 import unittest
 import warnings
 import weakref
@@ -2301,7 +2303,6 @@ for when, exp in (('S', 1),
             # Failures occur on some systems for MIDNIGHT and W0.
             # Print detailed calculation for MIDNIGHT so we can try to see
             # what's going on
-            import time
             if when == 'MIDNIGHT':
                 try:
                     if rh.utc:
@@ -2328,6 +2329,43 @@ for when, exp in (('S', 1),
         rh.close()
     setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
 
+class HandlerTest(BaseTest):
+
+    @unittest.skipUnless(threading, 'Threading required for this test.')
+    def test_race(self):
+        # Issue #14632 refers.
+        def remove_loop(fname, tries):
+            for _ in range(tries):
+                try:
+                    os.unlink(fname)
+                except OSError:
+                    pass
+                time.sleep(0.004 * random.randint(0, 4))
+
+        def cleanup(remover, fn, handler):
+            handler.close()
+            remover.join()
+            if os.path.exists(fn):
+                os.unlink(fn)
+
+        fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
+        os.close(fd)
+        del_count = 1000
+        log_count = 1000
+        remover = threading.Thread(target=remove_loop, args=(fn, del_count))
+        remover.daemon = True
+        remover.start()
+        for delay in (False, True):
+            h = logging.handlers.WatchedFileHandler(fn, delay=delay)
+            self.addCleanup(cleanup, remover, fn, h)
+            f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
+            h.setFormatter(f)
+            for _ in range(log_count):
+                time.sleep(0.005)
+                r = logging.makeLogRecord({'msg': 'testing' })
+                h.handle(r)
+
+
 # Set the locale to the platform-dependent default.  I have no idea
 # why the test does this, but in any case we save the current locale
 # first and restore it at the end.
@@ -2341,7 +2379,7 @@ def test_main():
                  LogRecordFactoryTest, ChildLoggerTest, QueueHandlerTest,
                  RotatingFileHandlerTest,
                  LastResortTest,
-                 TimedRotatingFileHandlerTest
+                 TimedRotatingFileHandlerTest, HandlerTest,
                 )
 
 if __name__ == "__main__":