From 9451a1c6ae14cc31ea88eaaf68d5a8f946b82831 Mon Sep 17 00:00:00 2001 From: Benjamin Peterson Date: Sat, 13 Mar 2010 22:30:34 +0000 Subject: [PATCH] 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 | 34 +++++++++++++ Lib/logging/__init__.py | 16 +++++-- Lib/logging/config.py | 21 ++++++-- Lib/logging/handlers.py | 8 +++- Lib/test/test_logging.py | 100 +++++++++++++++++++++++++++++++++++---- 5 files changed, 159 insertions(+), 20 deletions(-) diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index 6e809cd8477..c5997ef7247 100644 --- a/Doc/library/logging.rst +++ b/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 ------------- diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 073213fdc58..3d7ff82d2f4 100644 --- a/Lib/logging/__init__.py +++ b/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: diff --git a/Lib/logging/config.py b/Lib/logging/config.py index 767c630bd8a..beb51e5bb23 100644 --- a/Lib/logging/config.py +++ b/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) diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index 1e174e6a257..692d10428b1 100644 --- a/Lib/logging/handlers.py +++ b/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): """ diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 02ac00e0740..423f9d9981d 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -1,4 +1,4 @@ -#!/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)