cpython: 5de7c3d64f2a (original) (raw)

Mercurial > cpython

changeset 76544:5de7c3d64f2a 3.2

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

Vinay Sajip <vinay_sajip@yahoo.co.uk>
date	Tue, 24 Apr 2012 23:25:30 +0100
parents	0adf4fd8df83
children	380821b47872 59bc2d9497b0
files	Lib/logging/handlers.py Lib/test/test_logging.py
diffstat	2 files changed, 72 insertions(+), 23 deletions(-)[+] [-] Lib/logging/handlers.py 49 Lib/test/test_logging.py 46

line wrap: on

line diff

--- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -23,7 +23,7 @@ Copyright (C) 2001-2012 Vinay Sajip. All 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.FileHan """ 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):[](#l1.16)

       self.dev, self.ino = -1, -1[](#l1.17)

```
   else:[](#l1.18)
```

       stat = os.stat(self.baseFilename)[](#l1.19)

       self.dev, self.ino = stat[ST_DEV], stat[ST_INO][](#l1.20)

   self.dev, self.ino = -1, -1[](#l1.21)

```
   self._statstream()[](#l1.22)
```

def _statstream(self):
```
   if self.stream:[](#l1.25)
```

       sres = os.fstat(self.stream.fileno())[](#l1.26)

       self.dev, self.ino = sres[ST_DEV], sres[ST_INO][](#l1.27)

def emit(self, record): """ @@ -397,21 +399,30 @@ class WatchedFileHandler(logging.FileHan has, close the old stream and reopen the file to get the current stream. """

   if not os.path.exists(self.baseFilename):[](#l1.35)

```
       stat = None[](#l1.36)
```
```
       changed = 1[](#l1.37)
```
```
   else:[](#l1.38)
```

       stat = os.stat(self.baseFilename)[](#l1.39)

       changed = (stat[ST_DEV] != self.dev) or (stat[ST_INO] != self.ino)[](#l1.40)

   if changed and self.stream is not None:[](#l1.41)

```
       self.stream.flush()[](#l1.42)
```
```
       self.stream.close()[](#l1.43)
```

       self.stream = self._open()[](#l1.44)

```
       if stat is None:[](#l1.45)
```

           stat = os.stat(self.baseFilename)[](#l1.46)

       self.dev, self.ino = stat[ST_DEV], stat[ST_INO][](#l1.47)

   # Reduce the chance of race conditions by stat'ing by path only[](#l1.48)

   # once and then fstat'ing our new fd if we opened a new log stream.[](#l1.49)

   # See issue #14632: Thanks to John Mulligan for the problem report[](#l1.50)

```
   # and patch.[](#l1.51)
```
```
   try:[](#l1.52)
```

       # stat the file by path, checking for existence[](#l1.53)

       sres = os.stat(self.baseFilename)[](#l1.54)

```
   except OSError as err:[](#l1.55)
```

       if err.errno == errno.ENOENT:[](#l1.56)

```
           sres = None[](#l1.57)
```
```
       else:[](#l1.58)
```
```
           raise[](#l1.59)
```

   # compare file system stat with that of our stream file handle[](#l1.60)

   if not sres or sres[ST_DEV] != self.dev or sres[ST_INO] != self.ino:[](#l1.61)

       if self.stream is not None:[](#l1.62)

           # we have an open file handle, clean it up[](#l1.63)

           self.stream.flush()[](#l1.64)

           self.stream.close()[](#l1.65)

           # open a new file handle and get new stat info from that fd[](#l1.66)

           self.stream = self._open()[](#l1.67)

           self._statstream()[](#l1.68)
   logging.FileHandler.emit(self, record)[](#l1.69)

+ class SocketHandler(logging.Handler): """ A handler class which writes logging records, in pickle format, to

--- 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[](#l2.40)
       if when == 'MIDNIGHT':[](#l2.41)
           try:[](#l2.42)
               if rh.utc:[](#l2.43)

@@ -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.[](#l2.52)
```

   def remove_loop(fname, tries):[](#l2.53)

```
       for _ in range(tries):[](#l2.54)
```
```
           try:[](#l2.55)
```

               os.unlink(fname)[](#l2.56)

```
           except OSError:[](#l2.57)
```
```
               pass[](#l2.58)
```

           time.sleep(0.004 * random.randint(0, 4))[](#l2.59)

   def cleanup(remover, fn, handler):[](#l2.61)

```
       handler.close()[](#l2.62)
```
```
       remover.join()[](#l2.63)
```
```
       if os.path.exists(fn):[](#l2.64)
```
```
           os.unlink(fn)[](#l2.65)
```

   fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')[](#l2.67)

```
   os.close(fd)[](#l2.68)
```
```
   del_count = 1000[](#l2.69)
```
```
   log_count = 1000[](#l2.70)
```

   remover = threading.Thread(target=remove_loop, args=(fn, del_count))[](#l2.71)

```
   remover.daemon = True[](#l2.72)
```
```
   remover.start()[](#l2.73)
```

   for delay in (False, True):[](#l2.74)

       h = logging.handlers.WatchedFileHandler(fn, delay=delay)[](#l2.75)

       self.addCleanup(cleanup, remover, fn, h)[](#l2.76)

       f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')[](#l2.77)

```
       h.setFormatter(f)[](#l2.78)
```

       for _ in range(log_count):[](#l2.79)

```
           time.sleep(0.005)[](#l2.80)
```

           r = logging.makeLogRecord({'msg': 'testing' })[](#l2.81)

```
           h.handle(r)[](#l2.82)
```

+ +

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[](#l2.92)

            TimedRotatingFileHandlerTest, HandlerTest,[](#l2.93)
           )[](#l2.94)

if name == "main":