Merged revisions...

Merged revisions 77967,77969,77973,77979,77985-77986,78009,78029,78031-78033,78081,78085,78103,78105-78106,78108,78246,78703,78728,78731,78853,78855 via svnmerge from
svn+ssh://pythondev@svn.python.org/python/trunk

........
  r77967 | vinay.sajip | 2010-02-04 12:48:53 -0600 (Thu, 04 Feb 2010) | 1 line

  Logging: Implemented PEP 391.
........
  r77969 | vinay.sajip | 2010-02-04 14:18:28 -0600 (Thu, 04 Feb 2010) | 1 line

  Removed spurious print statement.
........
  r77973 | vinay.sajip | 2010-02-04 14:23:45 -0600 (Thu, 04 Feb 2010) | 1 line

  Issue #7851: logging: clarification on logging configuration files.
........
  r77979 | vinay.sajip | 2010-02-04 15:40:56 -0600 (Thu, 04 Feb 2010) | 1 line

  Added unit test for cfg:// resolution.
........
  r77985 | vinay.sajip | 2010-02-05 08:52:05 -0600 (Fri, 05 Feb 2010) | 1 line

  Issue #7857: test_logging: listener test now uses find_unused_port().
........
  r77986 | vinay.sajip | 2010-02-05 09:40:20 -0600 (Fri, 05 Feb 2010) | 1 line

  Issue #7857: test_logging: listener tests disabled for now.
........
  r78009 | vinay.sajip | 2010-02-05 17:43:11 -0600 (Fri, 05 Feb 2010) | 1 line

  test_logging: minor tweaks to timeouts, listening tests marked as skipped.
........
  r78029 | vinay.sajip | 2010-02-06 14:00:43 -0600 (Sat, 06 Feb 2010) | 1 line

  Issue #7857: Tentatively re-enabling one test to see effect on buildbots.
........
  r78031 | vinay.sajip | 2010-02-06 14:28:36 -0600 (Sat, 06 Feb 2010) | 1 line

  Issue #7857: Gave server thread more time to get ready, and re-enabled a skipped test.
........
  r78032 | georg.brandl | 2010-02-06 15:54:40 -0600 (Sat, 06 Feb 2010) | 1 line

  Remove unused imports from test_logging.
........
  r78033 | benjamin.peterson | 2010-02-06 16:08:15 -0600 (Sat, 06 Feb 2010) | 1 line

  make waiting for the server to start robust
........
  r78081 | vinay.sajip | 2010-02-07 06:56:54 -0600 (Sun, 07 Feb 2010) | 1 line

  Issue #7869: logging: improved format-time diagnostics and removed some 1.5.2 support code.
........
  r78085 | vinay.sajip | 2010-02-07 07:06:51 -0600 (Sun, 07 Feb 2010) | 1 line

  logging: Removed some more 1.5.2 support code.
........
  r78103 | vinay.sajip | 2010-02-08 00:50:14 -0600 (Mon, 08 Feb 2010) | 1 line

  Removed spurious print statement in test.
........
  r78105 | vinay.sajip | 2010-02-08 09:32:08 -0600 (Mon, 08 Feb 2010) | 1 line

  logging: skipped listening tests because they're not working reliably.
........
  r78106 | vinay.sajip | 2010-02-08 10:05:50 -0600 (Mon, 08 Feb 2010) | 1 line

  Issue #7857: Another attempt to keep the buildbots happy.
........
  r78108 | vinay.sajip | 2010-02-08 15:18:15 -0600 (Mon, 08 Feb 2010) | 1 line

  logging: gingerly re-enabling skipped tests after improving thread sync code in configurator.
........
  r78246 | vinay.sajip | 2010-02-19 17:53:17 -0600 (Fri, 19 Feb 2010) | 1 line

  logging: Documented warnings module integration.
........
  r78703 | vinay.sajip | 2010-03-05 16:11:24 -0600 (Fri, 05 Mar 2010) | 1 line

  Factored out time usage determination into a method, to facilitate alternative formatting implementations in the future.
........
  r78728 | vinay.sajip | 2010-03-06 09:12:08 -0600 (Sat, 06 Mar 2010) | 1 line

  Added schema version test in dictConfig.
........
  r78731 | vinay.sajip | 2010-03-06 09:56:03 -0600 (Sat, 06 Mar 2010) | 1 line

  Added checks for tuples in dictConfig.
........
  r78853 | vinay.sajip | 2010-03-12 00:01:21 -0600 (Fri, 12 Mar 2010) | 1 line

  Issue #8117: logging: Improved algorithm for computing initial rollover time.
........
  r78855 | vinay.sajip | 2010-03-12 03:16:10 -0600 (Fri, 12 Mar 2010) | 1 line

  Issue #8117: Updated NEWS entry and added to logging documentation.
........

Doc/library/logging.rst

@@ -420,6 +420,13 @@ You can see that the config file approach has a few advantages over the Python
 code approach, mainly separation of configuration and code and the ability of
 noncoders to easily modify the logging properties.
 
+Note that the class names referenced in config files need to be either relative
+to the logging module, or absolute values which can be resolved using normal
+import mechanisms. Thus, you could use either `handlers.WatchedFileHandler`
+(relative to the logging module) or `mypackage.mymodule.MyHandler` (for a
+class defined in package `mypackage` and module `mymodule`, where `mypackage`
+is available on the Python import path).
+
 .. _library-config:
 
 Configuring Logging for a Library
@@ -1849,6 +1856,11 @@ timed intervals.
    The extensions are date-and-time based, using the strftime format
    ``%Y-%m-%d_%H-%M-%S`` or a leading portion thereof, depending on the
    rollover interval.
+
+   When computing the next rollover time for the first time (when the handler
+   is created), the last modification time of an existing log file, or else
+   the current time, is used to compute when the next rotation will occur.
+
    If the *utc* argument is true, times in UTC will be used; otherwise
    local time is used.
 
@@ -2401,6 +2413,28 @@ module, you may not be able to use logging from within such handlers. This is
 because lock implementations in the :mod:`threading` module are not always
 re-entrant, and so cannot be invoked from such signal handlers.
 
+
+Integration with the warnings module
+------------------------------------
+
+The :func:`captureWarnings` function can be used to integrate :mod:`logging`
+with the :mod:`warnings` module.
+
+.. function:: captureWarnings(capture)
+
+   This function is used to turn the capture of warnings by logging on and
+   off.
+
+   If `capture` is `True`, warnings issued by the :mod:`warnings` module
+   will be redirected to the logging system. Specifically, a warning will be
+   formatted using :func:`warnings.formatwarning` and the resulting string
+   logged to a logger named "py.warnings" with a severity of `WARNING`.
+
+   If `capture` is `False`, the redirection of warnings to the logging system
+   will stop, and warnings will be redirected to their original destinations
+   (i.e. those in effect before `captureWarnings(True)` was called).
+
+
 Configuration
 -------------
 

Lib/logging/__init__.py

@@ -432,6 +432,12 @@ class Formatter(object):
             s = s[:-1]
         return s
 
+    def usesTime(self):
+        """
+        Check if the format uses the creation time of the record.
+        """
+        return self._fmt.find("%(asctime)") >= 0
+
     def format(self, record):
         """
         Format the specified record as text.
@@ -440,13 +446,13 @@ class Formatter(object):
         string formatting operation which yields the returned string.
         Before formatting the dictionary, a couple of preparatory steps
         are carried out. The message attribute of the record is computed
-        using LogRecord.getMessage(). If the formatting string contains
-        "%(asctime)", formatTime() is called to format the event time.
-        If there is exception information, it is formatted using
-        formatException() and appended to the message.
+        using LogRecord.getMessage(). If the formatting string uses the
+        time (as determined by a call to usesTime(), formatTime() is
+        called to format the event time. If there is exception information,
+        it is formatted using formatException() and appended to the message.
         """
         record.message = record.getMessage()
-        if self._fmt.find("%(asctime)") >= 0:
+        if self.usesTime():
             record.asctime = self.formatTime(record, self.datefmt)
         s = self._fmt % record.__dict__
         if record.exc_info:

Lib/logging/config.py

@@ -261,7 +261,6 @@ def _install_loggers(cp, handlers, disable_existing_loggers):
             logger.disabled = 1
 
 
-
 IDENTIFIER = re.compile('^[a-z_][a-z0-9_]*$', re.I)
 
 
@@ -448,7 +447,7 @@ class BaseConfigurator(object):
                  isinstance(value, tuple):
             value = ConvertingTuple(value)
             value.configurator = self
-        elif isinstance(value, str):
+        elif isinstance(value, str): # str for py3k
             m = self.CONVERT_PATTERN.match(value)
             if m:
                 d = m.groupdict()
@@ -474,6 +473,12 @@ class BaseConfigurator(object):
                 setattr(result, name, value)
         return result
 
+    def as_tuple(self, value):
+        """Utility function which converts lists to tuples."""
+        if isinstance(value, list):
+            value = tuple(value)
+        return value
+
 class DictConfigurator(BaseConfigurator):
     """
     Configure logging using a dictionary-like object to describe the
@@ -484,6 +489,10 @@ class DictConfigurator(BaseConfigurator):
         """Do the configuration."""
 
         config = self.config
+        if 'version' not in config:
+            raise ValueError("dictionary doesn't specify a version")
+        if config['version'] != 1:
+            raise ValueError("Unsupported version: %s" % config['version'])
         incremental = config.pop('incremental', False)
         EMPTY_DICT = {}
         logging._acquireLock()
@@ -684,6 +693,12 @@ class DictConfigurator(BaseConfigurator):
                 except Exception as e:
                     raise ValueError('Unable to set target handler '
                                      '%r: %s' % (config['target'], e))
+            elif issubclass(klass, logging.handlers.SMTPHandler) and\
+                'mailhost' in config:
+                config['mailhost'] = self.as_tuple(config['mailhost'])
+            elif issubclass(klass, logging.handlers.SysLogHandler) and\
+                'address' in config:
+                config['address'] = self.as_tuple(config['address'])
             factory = klass
         kwargs = dict([(k, config[k]) for k in config if valid_ident(k)])
         try:
@@ -788,7 +803,7 @@ def listen(port=DEFAULT_LOGGING_CONFIG_PORT):
                     chunk = self.connection.recv(slen)
                     while len(chunk) < slen:
                         chunk = chunk + conn.recv(slen - len(chunk))
-                    chunk = chunk.decode('utf-8')
+                    chunk = chunk.decode("utf-8")
                     try:
                         import json
                         d =json.loads(chunk)

Lib/logging/handlers.py

@@ -25,7 +25,7 @@ To use, simply 'import logging.handlers' and log away!
 """
 
 import logging, socket, os, pickle, struct, time, re
-from stat import ST_DEV, ST_INO
+from stat import ST_DEV, ST_INO, ST_MTIME
 
 try:
     import codecs
@@ -203,7 +203,11 @@ class TimedRotatingFileHandler(BaseRotatingHandler):
 
         self.extMatch = re.compile(self.extMatch, re.ASCII)
         self.interval = self.interval * interval # multiply by units requested
-        self.rolloverAt = self.computeRollover(int(time.time()))
+        if os.path.exists(filename):
+            t = os.stat(filename)[ST_MTIME]
+        else:
+            t = int(time.time())
+        self.rolloverAt = self.computeRollover(t)
 
     def computeRollover(self, currentTime):
         """

Lib/test/test_logging.py

-#!/usr/bin/env python3
+#!/usr/bin/env python
 #
 # Copyright 2001-2010 by Vinay Sajip. All Rights Reserved.
 #
@@ -26,7 +26,6 @@ import logging.handlers
 import logging.config
 
 import codecs
-import copy
 import pickle
 import io
 import gc
@@ -36,7 +35,6 @@ import re
 import select
 import socket
 from socketserver import ThreadingTCPServer, StreamRequestHandler
-import string
 import struct
 import sys
 import tempfile
@@ -44,8 +42,6 @@ from test.support import captured_stdout, run_with_locale, run_unittest,\
      find_unused_port
 import textwrap
 import threading
-import time
-import types
 import unittest
 import warnings
 import weakref
@@ -361,7 +357,7 @@ class CustomLevelsAndFiltersTest(BaseTest):
 
     def setUp(self):
         BaseTest.setUp(self)
-        for k, v in list(my_logging_levels.items()):
+        for k, v in my_logging_levels.items():
             logging.addLevelName(k, v)
 
     def log_at_all_levels(self, logger):
@@ -831,7 +827,7 @@ class MemoryTest(BaseTest):
         # Trigger cycle breaking.
         gc.collect()
         dead = []
-        for (id_, repr_), ref in list(self._survivors.items()):
+        for (id_, repr_), ref in self._survivors.items():
             if ref() is None:
                 dead.append(repr_)
         if dead:
@@ -870,7 +866,7 @@ class EncodingTest(BaseTest):
         # the non-ascii data we write to the log.
         data = "foo\x80"
         try:
-            handler = logging.FileHandler(fn, encoding="utf8")
+            handler = logging.FileHandler(fn, encoding="utf-8")
             log.addHandler(handler)
             try:
                 # write non-ascii data to the log.
@@ -879,7 +875,7 @@ class EncodingTest(BaseTest):
                 log.removeHandler(handler)
                 handler.close()
             # check we wrote exactly those bytes, ignoring trailing \n etc
-            f = open(fn, encoding="utf8")
+            f = open(fn, encoding="utf-8")
             try:
                 self.assertEqual(f.read().rstrip(), data)
             finally:
@@ -956,6 +952,7 @@ class ConfigDictTest(BaseTest):
 
     # config0 is a standard configuration.
     config0 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -977,6 +974,7 @@ class ConfigDictTest(BaseTest):
 
     # config1 adds a little to the standard configuration.
     config1 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1003,6 +1001,7 @@ class ConfigDictTest(BaseTest):
 
     # config2 has a subtle configuration error that should be reported
     config2 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1029,6 +1028,7 @@ class ConfigDictTest(BaseTest):
 
     #As config1 but with a misspelt level on a handler
     config2a = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1056,6 +1056,7 @@ class ConfigDictTest(BaseTest):
 
     #As config1 but with a misspelt level on a logger
     config2b = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1082,6 +1083,7 @@ class ConfigDictTest(BaseTest):
 
     # config3 has a less subtle configuration error
     config3 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1108,6 +1110,7 @@ class ConfigDictTest(BaseTest):
 
     # config4 specifies a custom formatter class to be loaded
     config4 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 '()' : __name__ + '.ExceptionFormatter',
@@ -1130,6 +1133,7 @@ class ConfigDictTest(BaseTest):
 
     # As config4 but using an actual callable rather than a string
     config4a = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 '()' : ExceptionFormatter,
@@ -1163,6 +1167,7 @@ class ConfigDictTest(BaseTest):
 
     # config5 specifies a custom handler class to be loaded
     config5 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1190,6 +1195,7 @@ class ConfigDictTest(BaseTest):
     # config6 specifies a custom handler class to be loaded
     # but has bad arguments
     config6 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1218,6 +1224,7 @@ class ConfigDictTest(BaseTest):
     #config 7 does not define compiler.parser but defines compiler.lexer
     #so compiler.parser should be disabled after applying it
     config7 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1243,6 +1250,7 @@ class ConfigDictTest(BaseTest):
     }
 
     config8 = {
+        'version': 1,
         'disable_existing_loggers' : False,
         'formatters': {
             'form1' : {
@@ -1271,6 +1279,7 @@ class ConfigDictTest(BaseTest):
     }
 
     config9 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1296,6 +1305,7 @@ class ConfigDictTest(BaseTest):
     }
 
     config9a = {
+        'version': 1,
         'incremental' : True,
         'handlers' : {
             'hand1' : {
@@ -1310,6 +1320,7 @@ class ConfigDictTest(BaseTest):
     }
 
     config9b = {
+        'version': 1,
         'incremental' : True,
         'handlers' : {
             'hand1' : {
@@ -1325,6 +1336,7 @@ class ConfigDictTest(BaseTest):
 
     #As config1 but with a filter added
     config10 = {
+        'version': 1,
         'formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1358,6 +1370,68 @@ class ConfigDictTest(BaseTest):
 
     #As config1 but using cfg:// references
     config11 = {
+        'version': 1,
+        'true_formatters': {
+            'form1' : {
+                'format' : '%(levelname)s ++ %(message)s',
+            },
+        },
+        'handler_configs': {
+            'hand1' : {
+                'class' : 'logging.StreamHandler',
+                'formatter' : 'form1',
+                'level' : 'NOTSET',
+                'stream'  : 'ext://sys.stdout',
+            },
+        },
+        'formatters' : 'cfg://true_formatters',
+        'handlers' : {
+            'hand1' : 'cfg://handler_configs[hand1]',
+        },
+        'loggers' : {
+            'compiler.parser' : {
+                'level' : 'DEBUG',
+                'handlers' : ['hand1'],
+            },
+        },
+        'root' : {
+            'level' : 'WARNING',
+        },
+    }
+
+    #As config11 but missing the version key
+    config12 = {
+        'true_formatters': {
+            'form1' : {
+                'format' : '%(levelname)s ++ %(message)s',
+            },
+        },
+        'handler_configs': {
+            'hand1' : {
+                'class' : 'logging.StreamHandler',
+                'formatter' : 'form1',
+                'level' : 'NOTSET',
+                'stream'  : 'ext://sys.stdout',
+            },
+        },
+        'formatters' : 'cfg://true_formatters',
+        'handlers' : {
+            'hand1' : 'cfg://handler_configs[hand1]',
+        },
+        'loggers' : {
+            'compiler.parser' : {
+                'level' : 'DEBUG',
+                'handlers' : ['hand1'],
+            },
+        },
+        'root' : {
+            'level' : 'WARNING',
+        },
+    }
+
+    #As config11 but using an unsupported version
+    config13 = {
+        'version': 2,
         'true_formatters': {
             'form1' : {
                 'format' : '%(levelname)s ++ %(message)s',
@@ -1573,13 +1647,19 @@ class ConfigDictTest(BaseTest):
     def test_config11_ok(self):
         self.test_config1_ok(self.config11)
 
+    def test_config12_failure(self):
+        self.assertRaises(Exception, self.apply_config, self.config12)
+
+    def test_config13_failure(self):
+        self.assertRaises(Exception, self.apply_config, self.config13)
+
     def setup_via_listener(self, text):
+        text = text.encode("utf-8")
         port = find_unused_port()
         t = logging.config.listen(port)
         t.start()
         t.ready.wait()
         t.ready.clear()
-        text = text.encode('utf-8')
         try:
             sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
             sock.settimeout(2.0)