diff options
| -rw-r--r-- | Lib/logging/handlers.py | 49 | ||||
| -rw-r--r-- | 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 index 9c63797..7a97c80 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 codecs import BOM_UTF8 from stat import ST_DEV, ST_INO, ST_MTIME import queue @@ -419,11 +419,13 @@ class WatchedFileHandler(logging.FileHandler): """ 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 @@ 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 = 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 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: |