From db81c4c63a702be1ec6e298bbee70634df873e68 Mon Sep 17 00:00:00 2001 From: Vinay Sajip Date: Thu, 25 Feb 2010 23:13:06 +0000 Subject: Merged revisions 77967,77969,78033,78055,78081,78085,78108 via svnmerge from svn+ssh://pythondev@svn.python.org/python/trunk ........ r77967 | vinay.sajip | 2010-02-04 18:48:53 +0000 (Thu, 04 Feb 2010) | 1 line Logging: Implemented PEP 391. ........ r77969 | vinay.sajip | 2010-02-04 20:18:28 +0000 (Thu, 04 Feb 2010) | 1 line Removed spurious print statement. ........ r78033 | benjamin.peterson | 2010-02-06 22:08:15 +0000 (Sat, 06 Feb 2010) | 1 line make waiting for the server to start robust ........ r78055 | vinay.sajip | 2010-02-07 01:37:08 +0000 (Sun, 07 Feb 2010) | 1 line Issue #7868: logging: added loggerClass attribute to Manager. ........ r78081 | vinay.sajip | 2010-02-07 12:56:54 +0000 (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 13:06:51 +0000 (Sun, 07 Feb 2010) | 1 line logging: Removed some more 1.5.2 support code. ........ r78108 | vinay.sajip | 2010-02-08 21:18:15 +0000 (Mon, 08 Feb 2010) | 1 line logging: gingerly re-enabling skipped tests after improving thread sync code in configurator. ........ --- Lib/logging/__init__.py | 26 +- Lib/logging/config.py | 565 +++++++++++++++++++++++++++++++++--- Lib/logging/handlers.py | 27 +- Lib/test/test_logging.py | 737 ++++++++++++++++++++++++++++++++++++++++++++++- Misc/NEWS | 6 + 5 files changed, 1286 insertions(+), 75 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 7becfda..073213f 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1,4 +1,4 @@ -# Copyright 2001-2009 by Vinay Sajip. All Rights Reserved. +# Copyright 2001-2010 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, @@ -46,8 +46,8 @@ except ImportError: __author__ = "Vinay Sajip " __status__ = "production" -__version__ = "0.5.1.1" -__date__ = "25 November 2009" +__version__ = "0.5.1.2" +__date__ = "07 February 2010" #--------------------------------------------------------------------------- # Miscellaneous module data @@ -767,7 +767,10 @@ class Handler(Filterer): if raiseExceptions: ei = sys.exc_info() try: - traceback.print_exception(ei[0], ei[1], ei[2], None, sys.stderr) + traceback.print_exception(ei[0], ei[1], ei[2], + None, sys.stderr) + sys.stderr.write('Logged from file %s, line %s\n' % ( + record.filename, record.lineno)) except IOError: pass # see issue 5971 finally: @@ -960,6 +963,7 @@ class Manager(object): self.disable = 0 self.emittedNoHandlerWarning = 0 self.loggerDict = {} + self.loggerClass = None def getLogger(self, name): """ @@ -979,13 +983,13 @@ class Manager(object): rv = self.loggerDict[name] if isinstance(rv, PlaceHolder): ph = rv - rv = _loggerClass(name) + rv = (self.loggerClass or _loggerClass)(name) rv.manager = self self.loggerDict[name] = rv self._fixupChildren(ph, rv) self._fixupParents(rv) else: - rv = _loggerClass(name) + rv = (self.loggerClass or _loggerClass)(name) rv.manager = self self.loggerDict[name] = rv self._fixupParents(rv) @@ -993,6 +997,16 @@ class Manager(object): _releaseLock() return rv + def setLoggerClass(self, klass): + """ + Set the class to be used when instantiating a logger with this Manager. + """ + if klass != Logger: + if not issubclass(klass, Logger): + raise TypeError("logger not derived from logging.Logger: " + + klass.__name__) + self.loggerClass = klass + def _fixupParents(self, alogger): """ Ensure that there are either loggers or placeholders all the way diff --git a/Lib/logging/config.py b/Lib/logging/config.py index 16316a9..767c630 100644 --- a/Lib/logging/config.py +++ b/Lib/logging/config.py @@ -1,4 +1,4 @@ -# Copyright 2001-2007 by Vinay Sajip. All Rights Reserved. +# Copyright 2001-2010 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, @@ -19,12 +19,13 @@ Configuration functions for the logging package for Python. The core package is based on PEP 282 and comments thereto in comp.lang.python, and influenced by Apache's log4j system. -Copyright (C) 2001-2009 Vinay Sajip. All Rights Reserved. +Copyright (C) 2001-2010 Vinay Sajip. All Rights Reserved. To use, simply 'import logging' and log away! """ -import sys, logging, logging.handlers, socket, struct, os, traceback +import sys, logging, logging.handlers, socket, struct, os, traceback, re +import types, io try: import _thread as thread @@ -57,10 +58,6 @@ def fileConfig(fname, defaults=None, disable_existing_loggers=True): the ability to select from various pre-canned configurations (if the developer provides a mechanism to present the choices and load the chosen configuration). - In versions of ConfigParser which have the readfp method [typically - shipped in 2.x versions of Python], you can pass in a file-like object - rather than a filename, in which case the file-like object will be read - using readfp. """ import configparser @@ -264,6 +261,496 @@ def _install_loggers(cp, handlers, disable_existing_loggers): logger.disabled = 1 + +IDENTIFIER = re.compile('^[a-z_][a-z0-9_]*$', re.I) + + +def valid_ident(s): + m = IDENTIFIER.match(s) + if not m: + raise ValueError('Not a valid Python identifier: %r' % s) + return True + + +# The ConvertingXXX classes are wrappers around standard Python containers, +# and they serve to convert any suitable values in the container. The +# conversion converts base dicts, lists and tuples to their wrapped +# equivalents, whereas strings which match a conversion format are converted +# appropriately. +# +# Each wrapper should have a configurator attribute holding the actual +# configurator to use for conversion. + +class ConvertingDict(dict): + """A converting dictionary wrapper.""" + + def __getitem__(self, key): + value = dict.__getitem__(self, key) + result = self.configurator.convert(value) + #If the converted value is different, save for next time + if value is not result: + self[key] = result + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + + def get(self, key, default=None): + value = dict.get(self, key, default) + result = self.configurator.convert(value) + #If the converted value is different, save for next time + if value is not result: + self[key] = result + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + + def pop(self, key, default=None): + value = dict.pop(self, key, default) + result = self.configurator.convert(value) + if value is not result: + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + +class ConvertingList(list): + """A converting list wrapper.""" + def __getitem__(self, key): + value = list.__getitem__(self, key) + result = self.configurator.convert(value) + #If the converted value is different, save for next time + if value is not result: + self[key] = result + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + + def pop(self, idx=-1): + value = list.pop(self, idx) + result = self.configurator.convert(value) + if value is not result: + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + return result + +class ConvertingTuple(tuple): + """A converting tuple wrapper.""" + def __getitem__(self, key): + value = tuple.__getitem__(self, key) + result = self.configurator.convert(value) + if value is not result: + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + +class BaseConfigurator(object): + """ + The configurator base class which defines some useful defaults. + """ + + CONVERT_PATTERN = re.compile(r'^(?P[a-z]+)://(?P.*)$') + + WORD_PATTERN = re.compile(r'^\s*(\w+)\s*') + DOT_PATTERN = re.compile(r'^\.\s*(\w+)\s*') + INDEX_PATTERN = re.compile(r'^\[\s*(\w+)\s*\]\s*') + DIGIT_PATTERN = re.compile(r'^\d+$') + + value_converters = { + 'ext' : 'ext_convert', + 'cfg' : 'cfg_convert', + } + + # We might want to use a different one, e.g. importlib + importer = __import__ + + def __init__(self, config): + self.config = ConvertingDict(config) + self.config.configurator = self + + def resolve(self, s): + """ + Resolve strings to objects using standard import and attribute + syntax. + """ + name = s.split('.') + used = name.pop(0) + found = self.importer(used) + for frag in name: + used += '.' + frag + try: + found = getattr(found, frag) + except AttributeError: + self.importer(used) + found = getattr(found, frag) + return found + + def ext_convert(self, value): + """Default converter for the ext:// protocol.""" + return self.resolve(value) + + def cfg_convert(self, value): + """Default converter for the cfg:// protocol.""" + rest = value + m = self.WORD_PATTERN.match(rest) + if m is None: + raise ValueError("Unable to convert %r" % value) + else: + rest = rest[m.end():] + d = self.config[m.groups()[0]] + #print d, rest + while rest: + m = self.DOT_PATTERN.match(rest) + if m: + d = d[m.groups()[0]] + else: + m = self.INDEX_PATTERN.match(rest) + if m: + idx = m.groups()[0] + if not self.DIGIT_PATTERN.match(idx): + d = d[idx] + else: + try: + n = int(idx) # try as number first (most likely) + d = d[n] + except TypeError: + d = d[idx] + if m: + rest = rest[m.end():] + else: + raise ValueError('Unable to convert ' + '%r at %r' % (value, rest)) + #rest should be empty + return d + + def convert(self, value): + """ + Convert values to an appropriate type. dicts, lists and tuples are + replaced by their converting alternatives. Strings are checked to + see if they have a conversion format and are converted if they do. + """ + if not isinstance(value, ConvertingDict) and isinstance(value, dict): + value = ConvertingDict(value) + value.configurator = self + elif not isinstance(value, ConvertingList) and isinstance(value, list): + value = ConvertingList(value) + value.configurator = self + elif not isinstance(value, ConvertingTuple) and\ + isinstance(value, tuple): + value = ConvertingTuple(value) + value.configurator = self + elif isinstance(value, str): + m = self.CONVERT_PATTERN.match(value) + if m: + d = m.groupdict() + prefix = d['prefix'] + converter = self.value_converters.get(prefix, None) + if converter: + suffix = d['suffix'] + converter = getattr(self, converter) + value = converter(suffix) + return value + + def configure_custom(self, config): + """Configure an object with a user-supplied factory.""" + c = config.pop('()') + if not hasattr(c, '__call__'): + c = self.resolve(c) + props = config.pop('.', None) + # Check for valid identifiers + kwargs = dict([(k, config[k]) for k in config if valid_ident(k)]) + result = c(**kwargs) + if props: + for name, value in props.items(): + setattr(result, name, value) + return result + +class DictConfigurator(BaseConfigurator): + """ + Configure logging using a dictionary-like object to describe the + configuration. + """ + + def configure(self): + """Do the configuration.""" + + config = self.config + incremental = config.pop('incremental', False) + EMPTY_DICT = {} + logging._acquireLock() + try: + if incremental: + handlers = config.get('handlers', EMPTY_DICT) + for name in handlers: + if name not in logging._handlers: + raise ValueError('No handler found with ' + 'name %r' % name) + else: + try: + handler = logging._handlers[name] + handler_config = handlers[name] + level = handler_config.get('level', None) + if level: + handler.setLevel(logging._checkLevel(level)) + except Exception as e: + raise ValueError('Unable to configure handler ' + '%r: %s' % (name, e)) + loggers = config.get('loggers', EMPTY_DICT) + for name in loggers: + try: + self.configure_logger(name, loggers[name], True) + except Exception as e: + raise ValueError('Unable to configure logger ' + '%r: %s' % (name, e)) + root = config.get('root', None) + if root: + try: + self.configure_root(root, True) + except Exception as e: + raise ValueError('Unable to configure root ' + 'logger: %s' % e) + else: + disable_existing = config.pop('disable_existing_loggers', True) + + logging._handlers.clear() + del logging._handlerList[:] + + # Do formatters first - they don't refer to anything else + formatters = config.get('formatters', EMPTY_DICT) + for name in formatters: + try: + formatters[name] = self.configure_formatter( + formatters[name]) + except Exception as e: + raise ValueError('Unable to configure ' + 'formatter %r: %s' % (name, e)) + # Next, do filters - they don't refer to anything else, either + filters = config.get('filters', EMPTY_DICT) + for name in filters: + try: + filters[name] = self.configure_filter(filters[name]) + except Exception as e: + raise ValueError('Unable to configure ' + 'filter %r: %s' % (name, e)) + + # Next, do handlers - they refer to formatters and filters + # As handlers can refer to other handlers, sort the keys + # to allow a deterministic order of configuration + handlers = config.get('handlers', EMPTY_DICT) + for name in sorted(handlers): + try: + handler = self.configure_handler(handlers[name]) + handler.name = name + handlers[name] = handler + except Exception as e: + raise ValueError('Unable to configure handler ' + '%r: %s' % (name, e)) + # Next, do loggers - they refer to handlers and filters + + #we don't want to lose the existing loggers, + #since other threads may have pointers to them. + #existing is set to contain all existing loggers, + #and as we go through the new configuration we + #remove any which are configured. At the end, + #what's left in existing is the set of loggers + #which were in the previous configuration but + #which are not in the new configuration. + root = logging.root + existing = list(root.manager.loggerDict.keys()) + #The list needs to be sorted so that we can + #avoid disabling child loggers of explicitly + #named loggers. With a sorted list it is easier + #to find the child loggers. + existing.sort() + #We'll keep the list of existing loggers + #which are children of named loggers here... + child_loggers = [] + #now set up the new ones... + loggers = config.get('loggers', EMPTY_DICT) + for name in loggers: + if name in existing: + i = existing.index(name) + prefixed = name + "." + pflen = len(prefixed) + num_existing = len(existing) + i = i + 1 # look at the entry after name + while (i < num_existing) and\ + (existing[i][:pflen] == prefixed): + child_loggers.append(existing[i]) + i = i + 1 + existing.remove(name) + try: + self.configure_logger(name, loggers[name]) + except Exception as e: + raise ValueError('Unable to configure logger ' + '%r: %s' % (name, e)) + + #Disable any old loggers. There's no point deleting + #them as other threads may continue to hold references + #and by disabling them, you stop them doing any logging. + #However, don't disable children of named loggers, as that's + #probably not what was intended by the user. + for log in existing: + logger = root.manager.loggerDict[log] + if log in child_loggers: + logger.level = logging.NOTSET + logger.handlers = [] + logger.propagate = True + elif disable_existing: + logger.disabled = True + + # And finally, do the root logger + root = config.get('root', None) + if root: + try: + self.configure_root(root) + except Exception as e: + raise ValueError('Unable to configure root ' + 'logger: %s' % e) + finally: + logging._releaseLock() + + def configure_formatter(self, config): + """Configure a formatter from a dictionary.""" + if '()' in config: + factory = config['()'] # for use in exception handler + try: + result = self.configure_custom(config) + except TypeError as te: + if "'format'" not in str(te): + raise + #Name of parameter changed from fmt to format. + #Retry with old name. + #This is so that code can be used with older Python versions + #(e.g. by Django) + config['fmt'] = config.pop('format') + config['()'] = factory + result = self.configure_custom(config) + else: + fmt = config.get('format', None) + dfmt = config.get('datefmt', None) + result = logging.Formatter(fmt, dfmt) + return result + + def configure_filter(self, config): + """Configure a filter from a dictionary.""" + if '()' in config: + result = self.configure_custom(config) + else: + name = config.get('name', '') + result = logging.Filter(name) + return result + + def add_filters(self, filterer, filters): + """Add filters to a filterer from a list of names.""" + for f in filters: + try: + filterer.addFilter(self.config['filters'][f]) + except Exception as e: + raise ValueError('Unable to add filter %r: %s' % (f, e)) + + def configure_handler(self, config): + """Configure a handler from a dictionary.""" + formatter = config.pop('formatter', None) + if formatter: + try: + formatter = self.config['formatters'][formatter] + except Exception as e: + raise ValueError('Unable to set formatter ' + '%r: %s' % (formatter, e)) + level = config.pop('level', None) + filters = config.pop('filters', None) + if '()' in config: + c = config.pop('()') + if not hasattr(c, '__call__') and hasattr(types, 'ClassType') and type(c) != types.ClassType: + c = self.resolve(c) + factory = c + else: + klass = self.resolve(config.pop('class')) + #Special case for handler which refers to another handler + if issubclass(klass, logging.handlers.MemoryHandler) and\ + 'target' in config: + try: + config['target'] = self.config['handlers'][config['target']] + except Exception as e: + raise ValueError('Unable to set target handler ' + '%r: %s' % (config['target'], e)) + factory = klass + kwargs = dict([(k, config[k]) for k in config if valid_ident(k)]) + try: + result = factory(**kwargs) + except TypeError as te: + if "'stream'" not in str(te): + raise + #The argument name changed from strm to stream + #Retry with old name. + #This is so that code can be used with older Python versions + #(e.g. by Django) + kwargs['strm'] = kwargs.pop('stream') + result = factory(**kwargs) + if formatter: + result.setFormatter(formatter) + if level is not None: + result.setLevel(logging._checkLevel(level)) + if filters: + self.add_filters(result, filters) + return result + + def add_handlers(self, logger, handlers): + """Add handlers to a logger from a list of names.""" + for h in handlers: + try: + logger.addHandler(self.config['handlers'][h]) + except Exception as e: + raise ValueError('Unable to add handler %r: %s' % (h, e)) + + def common_logger_config(self, logger, config, incremental=False): + """ + Perform configuration which is common to root and non-root loggers. + """ + level = config.get('level', None) + if level is not None: + logger.setLevel(logging._checkLevel(level)) + if not incremental: + #Remove any existing handlers + for h in logger.handlers[:]: + logger.removeHandler(h) + handlers = config.get('handlers', None) + if handlers: + self.add_handlers(logger, handlers) + filters = config.get('filters', None) + if filters: + self.add_filters(logger, filters) + + def configure_logger(self, name, config, incremental=False): + """Configure a non-root logger from a dictionary.""" + logger = logging.getLogger(name) + self.common_logger_config(logger, config, incremental) + propagate = config.get('propagate', None) + if propagate is not None: + logger.propagate = propagate + + def configure_root(self, config, incremental=False): + """Configure a root logger from a dictionary.""" + root = logging.getLogger() + self.common_logger_config(root, config, incremental) + +dictConfigClass = DictConfigurator + +def dictConfig(config): + """Configure logging using a dictionary.""" + dictConfigClass(config).configure() + + def listen(port=DEFAULT_LOGGING_CONFIG_PORT): """ Start up a socket server on the specified port, and listen for new @@ -301,24 +788,26 @@ def listen(port=DEFAULT_LOGGING_CONFIG_PORT): chunk = self.connection.recv(slen) while len(chunk) < slen: chunk = chunk + conn.recv(slen - len(chunk)) - #Apply new configuration. We'd like to be able to - #create a StringIO and pass that in, but unfortunately - #1.5.2 ConfigParser does not support reading file - #objects, only actual files. So we create a temporary - #file and remove it later. - file = tempfile.mktemp(".ini") - f = open(file, "w") - f.write(chunk) - f.close() + chunk = chunk.decode('utf-8') try: - fileConfig(file) - except (KeyboardInterrupt, SystemExit): - raise + import json + d =json.loads(chunk) + assert isinstance(d, dict) + dictConfig(d) except: - traceback.print_exc() - os.remove(file) + #Apply new configuration. + + file = io.StringIO(chunk) + try: + fileConfig(file) + except (KeyboardInterrupt, SystemExit): + raise + except: + traceback.print_exc() + if self.server.ready: + self.server.ready.set() except socket.error as e: - if not isinstancetype(e.args, tuple): + if not isinstance(e.args, tuple): raise else: errcode = e.args[0] @@ -333,12 +822,13 @@ def listen(port=DEFAULT_LOGGING_CONFIG_PORT): allow_reuse_address = 1 def __init__(self, host='localhost', port=DEFAULT_LOGGING_CONFIG_PORT, - handler=None): + handler=None, ready=None): ThreadingTCPServer.__init__(self, (host, port), handler) logging._acquireLock() self.abort = 0 logging._releaseLock() self.timeout = 1 + self.ready = ready def serve_until_stopped(self): import select @@ -353,17 +843,26 @@ def listen(port=DEFAULT_LOGGING_CONFIG_PORT): abort = self.abort logging._releaseLock() - def serve(rcvr, hdlr, port): - server = rcvr(port=port, handler=hdlr) - global _listener - logging._acquireLock() - _listener = server - logging._releaseLock() - server.serve_until_stopped() + class Server(threading.Thread): + + def __init__(self, rcvr, hdlr, port): + super(Server, self).__init__() + self.rcvr = rcvr + self.hdlr = hdlr + self.port = port + self.ready = threading.Event() + + def run(self): + server = self.rcvr(port=self.port, handler=self.hdlr, + ready=self.ready) + self.ready.set() + global _listener + logging._acquireLock() + _listener = server + logging._releaseLock() + server.serve_until_stopped() - return threading.Thread(target=serve, - args=(ConfigSocketReceiver, - ConfigStreamHandler, port)) + return Server(ConfigSocketReceiver, ConfigStreamHandler, port) def stopListening(): """ diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index fb48344..1e174e6 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -1,4 +1,4 @@ -# Copyright 2001-2009 by Vinay Sajip. All Rights Reserved. +# Copyright 2001-2010 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, @@ -19,7 +19,7 @@ Additional handlers for the logging package for Python. The core package is based on PEP 282 and comments thereto in comp.lang.python, and influenced by Apache's log4j system. -Copyright (C) 2001-2009 Vinay Sajip. All Rights Reserved. +Copyright (C) 2001-2010 Vinay Sajip. All Rights Reserved. To use, simply 'import logging.handlers' and log away! """ @@ -844,24 +844,6 @@ class SMTPHandler(logging.Handler): """ return self.subject - weekdayname = ['Mon', 'Tue', 'Wed', 'Thu', 'Fri', 'Sat', 'Sun'] - - monthname = [None, - 'Jan', 'Feb', 'Mar', 'Apr', 'May', 'Jun', - 'Jul', 'Aug', 'Sep', 'Oct', 'Nov', 'Dec'] - - def date_time(self): - """ - Return the current date and time formatted for a MIME header. - Needed for Python 1.5.2 (no email package available) - """ - year, month, day, hh, mm, ss, wd, y, z = time.gmtime(time.time()) - s = "%s, %02d %3s %4d %02d:%02d:%02d GMT" % ( - self.weekdayname[wd], - day, self.monthname[month], year, - hh, mm, ss) - return s - def emit(self, record): """ Emit a record. @@ -870,10 +852,7 @@ class SMTPHandler(logging.Handler): """ try: import smtplib - try: - from email.utils import formatdate - except ImportError: - formatdate = self.date_time + from email.utils import formatdate port = self.mailport if not port: port = smtplib.SMTP_PORT diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 0575149..cb6985e 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -30,6 +30,7 @@ import copy import pickle import io import gc +import json import os import re import select @@ -39,7 +40,8 @@ import string import struct import sys import tempfile -from test.support import captured_stdout, run_with_locale, run_unittest +from test.support import captured_stdout, run_with_locale, run_unittest,\ + find_unused_port import textwrap import threading import time @@ -85,6 +87,10 @@ class BaseTest(unittest.TestCase): level.""" self.stream.close() self.root_logger.removeHandler(self.root_hdlr) + while self.root_logger.handlers: + h = self.root_logger.handlers[0] + self.root_logger.removeHandler(h) + h.close() self.root_logger.setLevel(self.original_logging_level) logging._acquireLock() try: @@ -632,14 +638,8 @@ class ConfigFileTest(BaseTest): """ def apply_config(self, conf): - try: - fn = tempfile.mktemp(".ini") - f = open(fn, "w") - f.write(textwrap.dedent(conf)) - f.close() - logging.config.fileConfig(fn) - finally: - os.remove(fn) + file = io.StringIO(textwrap.dedent(conf)) + logging.config.fileConfig(file) def test_config0_ok(self): # A simple config file which overrides the default settings. @@ -938,15 +938,728 @@ class WarningsTest(BaseTest): finally: logging.captureWarnings(False) + +def formatFunc(format, datefmt=None): + return logging.Formatter(format, datefmt) + +def handlerFunc(): + return logging.StreamHandler() + +class CustomHandler(logging.StreamHandler): + pass + +class ConfigDictTest(BaseTest): + + """Reading logging config from a dictionary.""" + + expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" + + # config0 is a standard configuration. + config0 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'root' : { + 'level' : 'WARNING', + 'handlers' : ['hand1'], + }, + } + + # config1 adds a little to the standard configuration. + config1 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + # config2 has a subtle configuration error that should be reported + config2 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdbout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + #As config1 but with a misspelt level on a handler + config2a = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NTOSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + + #As config1 but with a misspelt level on a logger + config2b = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WRANING', + }, + } + + # config3 has a less subtle configuration error + config3 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'misspelled_name', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + # config4 specifies a custom formatter class to be loaded + config4 = { + 'formatters': { + 'form1' : { + '()' : __name__ + '.ExceptionFormatter', + 'format' : '%(levelname)s:%(name)s:%(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'root' : { + 'level' : 'NOTSET', + 'handlers' : ['hand1'], + }, + } + + # As config4 but using an actual callable rather than a string + config4a = { + 'formatters': { + 'form1' : { + '()' : ExceptionFormatter, + 'format' : '%(levelname)s:%(name)s:%(message)s', + }, + 'form2' : { + '()' : __name__ + '.formatFunc', + 'format' : '%(levelname)s:%(name)s:%(message)s', + }, + 'form3' : { + '()' : formatFunc, + 'format' : '%(levelname)s:%(name)s:%(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + 'hand2' : { + '()' : handlerFunc, + }, + }, + 'root' : { + 'level' : 'NOTSET', + 'handlers' : ['hand1'], + }, + } + + # config5 specifies a custom handler class to be loaded + config5 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : __name__ + '.CustomHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + # config6 specifies a custom handler class to be loaded + # but has bad arguments + config6 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : __name__ + '.CustomHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + '9' : 'invalid parameter name', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + #config 7 does not define compiler.parser but defines compiler.lexer + #so compiler.parser should be disabled after applying it + config7 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.lexer' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + config8 = { + 'disable_existing_loggers' : False, + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler' : { + 'level' : 'DEBUG', + 'handlers' : ['hand1'], + }, + 'compiler.lexer' : { + }, + }, + 'root' : { + 'level' : 'WARNING', + }, + } + + config9 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'WARNING', + 'stream' : 'ext://sys.stdout', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'WARNING', + 'handlers' : ['hand1'], + }, + }, + 'root' : { + 'level' : 'NOTSET', + }, + } + + config9a = { + 'incremental' : True, + 'handlers' : { + 'hand1' : { + 'level' : 'WARNING', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'INFO', + }, + }, + } + + config9b = { + 'incremental' : True, + 'handlers' : { + 'hand1' : { + 'level' : 'INFO', + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'INFO', + }, + }, + } + + #As config1 but with a filter added + config10 = { + 'formatters': { + 'form1' : { + 'format' : '%(levelname)s ++ %(message)s', + }, + }, + 'filters' : { + 'filt1' : { + 'name' : 'compiler.parser', + }, + }, + 'handlers' : { + 'hand1' : { + 'class' : 'logging.StreamHandler', + 'formatter' : 'form1', + 'level' : 'NOTSET', + 'stream' : 'ext://sys.stdout', + 'filters' : ['filt1'], + }, + }, + 'loggers' : { + 'compiler.parser' : { + 'level' : 'DEBUG', + 'filters' : ['filt1'], + }, + }, + 'root' : { + 'level' : 'WARNING', + 'handlers' : ['hand1'], + }, + } + + #As config1 but using cfg:// references + config11 = { + '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', + }, + } + + def apply_config(self, conf): + logging.config.dictConfig(conf) + + def test_config0_ok(self): + # A simple config which overrides the default settings. + with captured_stdout() as output: + self.apply_config(self.config0) + logger = logging.getLogger() + # Won't output anything + logger.info(self.next_message()) + # Outputs a message + logger.error(self.next_message()) + self.assert_log_lines([ + ('ERROR', '2'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + + def test_config1_ok(self, config=config1): + # A config defining a sub-parser as well. + with captured_stdout() as output: + self.apply_config(config) + logger = logging.getLogger("compiler.parser") + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + self.assert_log_lines([ + ('INFO', '1'), + ('ERROR', '2'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + + def test_config2_failure(self): + # A simple config which overrides the default settings. + self.assertRaises(Exception, self.apply_config, self.config2) + + def test_config2a_failure(self): + # A simple config which overrides the default settings. + self.assertRaises(Exception, self.apply_config, self.config2a) + + def test_config2b_failure(self): + # A simple config which overrides the default settings. + self.assertRaises(Exception, self.apply_config, self.config2b) + + def test_config3_failure(self): + # A simple config which overrides the default settings. + self.assertRaises(Exception, self.apply_config, self.config3) + + def test_config4_ok(self): + # A config specifying a custom formatter class. + with captured_stdout() as output: + self.apply_config(self.config4) + #logger = logging.getLogger() + try: + raise RuntimeError() + except RuntimeError: + logging.exception("just testing") + sys.stdout.seek(0) + self.assertEquals(output.getvalue(), + "ERROR:root:just testing\nGot a [RuntimeError]\n") + # Original logger output is empty + self.assert_log_lines([]) + + def test_config4a_ok(self): + # A config specifying a custom formatter class. + with captured_stdout() as output: + self.apply_config(self.config4a) + #logger = logging.getLogger() + try: + raise RuntimeError() + except RuntimeError: + logging.exception("just testing") + sys.stdout.seek(0) + self.assertEquals(output.getvalue(), + "ERROR:root:just testing\nGot a [RuntimeError]\n") + # Original logger output is empty + self.assert_log_lines([]) + + def test_config5_ok(self): + self.test_config1_ok(config=self.config5) + + def test_config6_failure(self): + self.assertRaises(Exception, self.apply_config, self.config6) + + def test_config7_ok(self): + with captured_stdout() as output: + self.apply_config(self.config1) + logger = logging.getLogger("compiler.parser") + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + self.assert_log_lines([ + ('INFO', '1'), + ('ERROR', '2'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + with captured_stdout() as output: + self.apply_config(self.config7) + logger = logging.getLogger("compiler.parser") + self.assertTrue(logger.disabled) + logger = logging.getLogger("compiler.lexer") + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + self.assert_log_lines([ + ('INFO', '3'), + ('ERROR', '4'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + + #Same as test_config_7_ok but don't disable old loggers. + def test_config_8_ok(self): + with captured_stdout() as output: + self.apply_config(self.config1) + logger = logging.getLogger("compiler.parser") + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + self.assert_log_lines([ + ('INFO', '1'), + ('ERROR', '2'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + with captured_stdout() as output: + self.apply_config(self.config8) + logger = logging.getLogger("compiler.parser") + self.assertFalse(logger.disabled) + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + logger = logging.getLogger("compiler.lexer") + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + self.assert_log_lines([ + ('INFO', '3'), + ('ERROR', '4'), + ('INFO', '5'), + ('ERROR', '6'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + + def test_config_9_ok(self): + with captured_stdout() as output: + self.apply_config(self.config9) + logger = logging.getLogger("compiler.parser") + #Nothing will be output since both handler and logger are set to WARNING + logger.info(self.next_message()) + self.assert_log_lines([], stream=output) + self.apply_config(self.config9a) + #Nothing will be output since both handler is still set to WARNING + logger.info(self.next_message()) + self.assert_log_lines([], stream=output) + self.apply_config(self.config9b) + #Message should now be output + logger.info(self.next_message()) + self.assert_log_lines([ + ('INFO', '3'), + ], stream=output) + + def test_config_10_ok(self): + with captured_stdout() as output: + self.apply_config(self.config10) + logger = logging.getLogger("compiler.parser") + logger.warning(self.next_message()) + logger = logging.getLogger('compiler') + #Not output, because filtered + logger.warning(self.next_message()) + logger = logging.getLogger('compiler.lexer') + #Not output, because filtered + logger.warning(self.next_message()) + logger = logging.getLogger("compiler.parser.codegen") + #Output, as not filtered + logger.error(self.next_message()) + self.assert_log_lines([ + ('WARNING', '1'), + ('ERROR', '4'), + ], stream=output) + + def test_config11_ok(self): + self.test_config1_ok(self.config11) + + def setup_via_listener(self, text): + 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) + sock.connect(('localhost', port)) + + slen = struct.pack('>L', len(text)) + s = slen + text + sentsofar = 0 + left = len(s) + while left > 0: + sent = sock.send(s[sentsofar:]) + sentsofar += sent + left -= sent + sock.close() + finally: + t.ready.wait(2.0) + logging.config.stopListening() + t.join(2.0) + + def test_listen_config_10_ok(self): + with captured_stdout() as output: + self.setup_via_listener(json.dumps(self.config10)) + logger = logging.getLogger("compiler.parser") + logger.warning(self.next_message()) + logger = logging.getLogger('compiler') + #Not output, because filtered + logger.warning(self.next_message()) + logger = logging.getLogger('compiler.lexer') + #Not output, because filtered + logger.warning(self.next_message()) + logger = logging.getLogger("compiler.parser.codegen") + #Output, as not filtered + logger.error(self.next_message()) + self.assert_log_lines([ + ('WARNING', '1'), + ('ERROR', '4'), + ], stream=output) + + def test_listen_config_1_ok(self): + with captured_stdout() as output: + self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1)) + logger = logging.getLogger("compiler.parser") + # Both will output a message + logger.info(self.next_message()) + logger.error(self.next_message()) + self.assert_log_lines([ + ('INFO', '1'), + ('ERROR', '2'), + ], stream=output) + # Original logger output is empty. + self.assert_log_lines([]) + + +class ManagerTest(BaseTest): + def test_manager_loggerclass(self): + logged = [] + + class MyLogger(logging.Logger): + def _log(self, level, msg, args, exc_info=None, extra=None): + logged.append(msg) + + man = logging.Manager(None) + self.assertRaises(TypeError, man.setLoggerClass, int) + man.setLoggerClass(MyLogger) + logger = man.getLogger('test') + logger.warning('should appear in logged') + logging.warning('should not appear in logged') + + self.assertEqual(logged, ['should appear in logged']) + + # 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. @run_with_locale('LC_ALL', '') def test_main(): run_unittest(BuiltinLevelsTest, BasicFilterTest, - CustomLevelsAndFiltersTest, MemoryHandlerTest, - ConfigFileTest, SocketHandlerTest, MemoryTest, - EncodingTest, WarningsTest) + CustomLevelsAndFiltersTest, MemoryHandlerTest, + ConfigFileTest, SocketHandlerTest, MemoryTest, + EncodingTest, WarningsTest, ConfigDictTest, ManagerTest) if __name__ == "__main__": test_main() diff --git a/Misc/NEWS b/Misc/NEWS index e384a92..81dfbc0 100644 --- a/Misc/NEWS +++ b/Misc/NEWS @@ -260,6 +260,12 @@ C-API Library ------- +- Issue #7869: logging: improved diagnostic for format-time errors. + +- Issue #7868: logging: added loggerClass attribute to Manager. + +- logging: Implemented PEP 391. + - Issue #1537721: Add a writeheader() method to csv.DictWriter. - Issue #7959: ctypes callback functions are now registered correctly -- cgit v0.12