[Python-checkins] cpython (merge 3.2 -> default): Issue #14632: Updated WatchedFileHandler to deal with race condition. Thanks to

Wed Apr 25 00:33:46 CEST 2012

http://hg.python.org/cpython/rev/380821b47872
changeset: 76545:380821b47872
parent: 76541:08d4c2fe51ea
parent: 76544:5de7c3d64f2a
user: Vinay Sajip <vinay_sajip at yahoo.co.uk>
date: Tue Apr 24 23:33:33 2012 +0100
summary:
 Issue #14632: Updated WatchedFileHandler to deal with race condition. Thanks to John Mulligan for the problem report and patch.
files:
 Lib/logging/handlers.py | 49 +++++++++++++++++----------
 Lib/test/test_logging.py | 45 ++++++++++++++++++++++--
 2 files changed, 70 insertions(+), 24 deletions(-)

diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py
--- a/Lib/logging/handlers.py
+++ b/Lib/logging/handlers.py
@@ -23,7 +23,7 @@
 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 codecs import BOM_UTF8
 from stat import ST_DEV, ST_INO, ST_MTIME
 import queue
@@ -419,11 +419,13 @@
 """
 def __init__(self, filename, mode='a', encoding=None, delay=False):
 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):
 """
@@ -433,21 +435,30 @@
 has, close the old stream and reopen the file to get the
 current stream.
 """
- if not os.path.exists(self.baseFilename):
- stat = None
- changed = True
- 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
--- 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 json
 import os
 import queue
+import random
 import re
 import select
 import socket
@@ -539,8 +540,8 @@
 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 @@
 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 @@
 # 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:
-- 
Repository URL: http://hg.python.org/cpython
