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

1 files changed, 40 insertions, 5 deletions

diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index 75b3e4d..ee1c211 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
@@ -539,8 +540,8 @@ class HandlerTest(BaseTest):
                 h = logging.handlers.WatchedFileHandler(fn, delay=True)
                 if existing:
                     dev, ino = h.dev, h.ino
-                    self.assertNotEqual(dev, -1)
-                    self.assertNotEqual(ino, -1)
+                    self.assertEqual(dev, -1)
+                    self.assertEqual(ino, -1)
                     r = logging.makeLogRecord({'msg': 'Test'})
                     h.handle(r)
                     # Now remove the file.
@@ -581,6 +582,41 @@ class HandlerTest(BaseTest):
         self.assertFalse(h.shouldFlush(r))
         h.close()
 
+    @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)
+
+
 class BadStream(object):
     def write(self, data):
         raise RuntimeError('deliberate mistake')
@@ -3724,7 +3760,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: