diff options
| -rw-r--r-- | Lib/logging/handlers.py | 49 | ||||
| -rw-r--r-- | Lib/test/test_logging.py | 46 |
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__": |