PEP: 282
Title: A Logging System
Version: $Revision: 1.1 $
Last-Modified: $Date: 2002/02/15 04:09:17 $
Author: vinay_sajip at red-dove.com (Vinay Sajip)
Status: Draft
Type: Standards Track
Created: 4-Feb-2002
Python-Version: 2.3
Post-History:


Abstract

    This PEP describes a proposed logging package for Python's
    standard library.

    Basically the system involves the user creating one or more
    logger objects on which methods are called to log debugging
    notes, general information, warnings, errors etc.  Different
    logging 'levels' can be used to distinguish important messages
    from less important ones.

    A registry of named singleton logger objects is maintained so that

        1) different logical logging streams (or 'channels') exist
           (say, one for 'zope.zodb' stuff and another for
           'mywebsite'-specific stuff)

        2) one does not have to pass logger object references around.

    The system is configurable at runtime.  This configuration
    mechanism allows one to tune the level and type of logging done
    while not touching the application itself.


Motivation

    If a single logging mechanism is enshrined in the standard
    library, 1) logging is more likely to be done 'well', and 2)
    multiple libraries will be able to be integrated into larger
    applications which can be logged reasonably coherently.


Influences

    This proposal was put together after having studied the
    following logging packages:

        o java.util.logging in JDK 1.4 (a.k.a. JSR047) [1]
        o log4j [2]
        o the Syslog package from the Protomatter project [3]
        o MAL's mx.Log package [4]


Simple Example

    This shows a very simple example of how the logging package can be
    used to generate simple logging output on stderr.

        --------- mymodule.py -------------------------------
				import logging
				log = logging.getLogger("MyModule")

				def doIt():
					log.debug("Doin' stuff...")
					#do stuff...
					raise TypeError, "Bogus type error for testing"
        -----------------------------------------------------

        --------- myapp.py ----------------------------------
        import mymodule, logging

				logging.basicConfig()

				log = logging.getLogger("MyApp")

				log.info("Starting my app")
				try:
					mymodule.doIt()
				except Exception, e:
					log.exception("There was a problem.")
				log.info("Ending my app")
        -----------------------------------------------------

    > python myapp.py

		INFO:MyApp: Starting my app
		DEBUG:MyModule: Doin' stuff...
		ERROR:MyApp: There was a problem.
		Traceback (most recent call last):
			File "myapp.py", line 9, in ?
				mymodule.doIt()
			File "mymodule.py", line 7, in doIt
				raise TypeError, "Bogus type error for testing"
		TypeError: Bogus type error for testing

		INFO:MyApp: Ending my app

		The above example shows the default output format. All aspects
		of the output format should be configurable, so that you could have
		output formatted like this:

		2002-04-19 07:56:58,174 MyModule   DEBUG - Doin' stuff...

		or just

		Doin' stuff...


Control Flow

    Applications make logging calls on *Logger* objects.  Loggers are
    organized in a hierarchical namespace and child Loggers inherit some
    logging properties from their parents in the namespace.

    Logger names fit into a "dotted name" namespace, with dots (periods)
    indicating sub-namespaces.  The namespace of logger objects therefore
    corresponds to a single tree data structure.

       "" is the root of the namespace
       "Zope" would be a child node of the root
       "Zope.ZODB" would be a child node of "Zope"

    These Logger objects create *LogRecord* objects which are passed
    to *Handler* objects for output.  Both Loggers and Handlers
    may use logging *levels* and (optionally) *Filters* to decide if
    they are interested in a particular LogRecord.  When it is
    necessary to output a LogRecord externally, a Handler can
    (optionally) use a *Formatter* to localize and format the message
    before sending it to an I/O stream.

    Each Logger keeps track of a set of output Handlers.  By default
    all Loggers also send their output to all Handlers of their
    ancestor Loggers.  Loggers may, however, also be configured to
    ignore Handlers higher up the tree.

    The APIs are structured so that calls on the Logger APIs can be
    cheap when logging is disabled.  If logging is disabled for a
    given log level, then the Logger can make a cheap comparison test
    and return.  If logging is enabled for a given log level, the
    Logger is still careful to minimize costs before passing the
    LogRecord into the Handlers.  In particular, localization and
    formatting (which are relatively expensive) are deferred until the
    Handler requests them.

    The overall Logger hierarchy can also have a level associated with
    it, which takes precedence over the levels of individual Loggers.
   	This is done through a module-level function:

   	def disable(lvl):
			"""
			Do not generate any LogRecords for requests with a severity less
			than 'lvl'.
			"""
			...


Levels

    The logging levels, in increasing order of importance, are:

        DEBUG
        INFO
        WARN
        ERROR
        CRITICAL

		The term CRITICAL is used in preference to FATAL, which is used by log4j.
		The levels are conceptually the same - that of a serious, or very serious,
		error. However, FATAL implies death, which in Python implies a raised and
		uncaught exception, traceback, and exit.  Since the logging module does not
		enforce such an outcome from a FATAL-level log entry, it makes sense to use
		CRITICAL in preference to FATAL.

    These are just integer constants, to allow simple comparison of importance.
    Experience has shown that too many levels can be confusing, as they lead
    to subjective interpretation of which level should be applied to any
    particular log request.

		Although the above levels are strongly recommended, the logging system
		should not be prescriptive. Users may define their own levels, as well
		as the textual representation of any levels. User defined levels must,
		however, obey the constraints that they are all positive integers and
		that they increase in order of increasing severity.

		User-defined logging levels are supported through two module-level
		functions:

			def getLevelName(lvl):
				"""Return the text for level 'lvl'."""
				...

			def addLevelName(lvl, lvlName):
				"""
				Add the level 'lvl' with associated text 'levelName', or
				set the textual representation of existing level 'lvl' to be
				'lvlName'."""
				...

Loggers

    Each Logger object keeps track of a log level (or threshold) that
    it is interested in, and discards log requests below that level.

    A *Manager* class instance maintains the hierarchical namespace of named
    Logger objects.  Generations are denoted with dot-separated names:
    Logger "foo" is the parent of Loggers "foo.bar" and "foo.baz".

		The Manager class instance is a singleton and is not directly exposed to
		users, who interact with it using various module-level functions.

    The general logging method is:

        class Logger:
            def log(self, lvl, msg, *args, **kwargs):
                """Log 'str(msg) % args' at logging level 'lvl'."""
                ...

    However, convenience functions are defined for each logging level:

				class Logger:
						def debug(self, msg, *args, **kwargs): ...
						def info(self, msg, *args, **kwargs): ...
						def warn(self, msg, *args, **kwargs): ...
						def error(self, msg, *args, **kwargs): ...
						def critical(self, msg, *args, **kwargs): ...

    Only one keyword argument is recognized at present - "exc_info".
    If true, the caller wants exception information to be provided in
    the logging output. This mechanism is only needed if exception
    information needs to be provided at *any* logging level. In the more
    common case, where exception information needs to be added to the
    log only when errors occur, i.e. at the ERROR level, then
    another convenience method is provided:

				class Logger:
		    		def exception(self, msg, *args): ...

    This should only be called in the context of an exception handler, and
    is the preferred way of indicating a desire for exception information in
    the log. The other convenience methods are intended to be called with
    exc_info only in the unusual situation where you might want to provide
    exception information in the context of an INFO message, for example.

		The "msg" argument shown above will normally be a format string; however,
		it can be any object x for which str(x) returns the format string. This
		facilitates, for example, the use of an object which fetches a locale-
		specific message for an internationalized/localized application, perhaps
		using the standard gettext module. An outline example:

				class Message:
					"""Represents a message"""
					def __init__(self, id):
							"""Initialize with the message ID"""

					def __str__(self):
						"""Return an appropriate localized message text"""

				...

				logger.info(Message("abc"), ...)

		Gathering and formatting data for a log message may be expensive, and a
		waste if the logger was going to discard the message anyway.  To see if
		a request will be honoured by the logger, the isEnabledFor() method can
		be used:

				class Logger:
						def isEnabledFor(self, lvl):
								"""
								Return true if requests at level 'lvl' will NOT be
								discarded.
								"""
                ...

		so instead of this expensive and possibly wasteful DOM to XML
    conversion:

				...
				hamletStr = hamletDom.toxml()
				log.info(hamletStr)
				...

		one can do this:

				if log.isEnabledFor(logging.INFO):
						hamletStr = hamletDom.toxml()
						log.info(hamletStr)

		When new loggers are created, they are initialized with a level which
		signifies "no level". A level can be set explicitly using the setLevel()
		method:

				class Logger:
						def setLevel(self, lvl): ...

		If a logger's level is not set, the system consults all its ancestors,
		walking up the hierarchy until an explicitly set level is found. That
		is regarded as the "effective level" of the logger, and can be queried
		via the getEffectiveLevel() method:

				def getEffectiveLevel(self): ...

		Loggers are never instantiated directly. Instead, a module-level function
		is used:

				def getLogger(name=None): ...

		If no name is specified, the root logger is returned. Otherwise, if a
		logger with that name exists, it is returned. If not, a new logger is
		initialized and returned. Here, "name" is synonymous with "channel name".

		Users can specify a custom subclass of Logger to be used by the
		system when instantiating new loggers:

				def setLoggerClass(klass): ...

		The passed class should be a subclass of Logger, and it's __init__ method
		should call Logger.__init__.


Handlers

    Handlers are responsible for doing something useful with a given
    LogRecord.  The following core Handlers will be implemented:

        - StreamHandler: A handler for writing to a file-like object.
        - FileHandler: A handler for writing to a single file or set
          of rotating files.
        - SocketHandler: A handler for writing to remote TCP ports.
        - DatagramHandler: A handler for writing to UDP sockets, for
          low-cost logging.  Jeff Bauer already had such a system [5].
        - MemoryHandler: A handler that buffers log records in memory
          until the buffer is full or a particular condition occurs
          [1].
        - SMTPHandler: A handler for sending to email addresses via
        	SMTP.
        - SysLogHandler: A handler for writing to Unix syslog via
        	UDP.
        - NTEventLogHandler: A handler for writing to event logs on
        	Windows NT, 2000 and XP.
				- HTTPHandler: A handler for writing to a Web server with
					either GET or POST semantics.

		Handlers can also have levels set for them using the setLevel()
		method:

				def setLevel(self, lvl): ...


		The FileHandler can be set up to create a rotating set of log files.
		In this case, the file name passed to the constructor is taken as a
		"base" file name. Additional file names for the rotation are created
		by appending .1, .2, etc. to the base file name, up to a maximum
		as specified when rollover is requested.  The setRollover method is
		used to specify a maximum size for a log file and a maximum number of
		backup files in the rotation.

				def setRollover(maxBytes, backupCount): ...

		If maxBytes is specified as zero, no rollover ever occurs and the
		log file grows indefinitely. If a non-zero size is specified, when
		that size is about to be exceeded, rollover occurs. The rollover
		method ensures that the base file name is always the most recent,
		.1 is the next most recent, .2 the next most recent after that,
		and so on.

		There are many additional handlers implemented in the test/example
		scripts provided with [6] - for example, XMLHandler and SOAPHandler.

LogRecords

	A LogRecord acts as a receptacle for information about a logging event.
	It is little more than a dictionary, though it does define a getMessage
	method which merges a message with optional runarguments.

Formatters

    A Formatter is responsible for converting a LogRecord to a string
    representation.  A Handler may call its Formatter before writing a
    record.  The following core Formatters will be implemented:

        - Formatter: Provide printf-like formatting, using the % operator.

				- BufferingFormatter: Provide formatting for multiple messages,
					with header and trailer formatting support.

		Formatters are associated with Handlers by calling setFormatter() on
		a handler:

				def setFormatter(self, form): ...

		Formatters use the % operator to format the logging message. The format
		string should contain %(name)x and the attribute dictionary of the
		LogRecord is used to obtain message-specific data. The following
		attributes are provided:

		%(name)s            Name of the logger (logging channel)
		%(levelno)s         Numeric logging level for the message (DEBUG, INFO,
												WARN, ERROR, CRITICAL)
		%(levelname)s       Text logging level for the message ("DEBUG", "INFO",
												"WARN", "ERROR", "CRITICAL")
		%(pathname)s        Full pathname of the source file where the logging
												call was issued (if available)
		%(filename)s        Filename portion of pathname
		%(module)s          Module from which logging call was made
		%(lineno)d          Source line number where the logging call was issued
												(if available)
		%(created)f         Time when the LogRecord was created (time.time()
												return value)
		%(asctime)s         Textual time when the LogRecord was created
		%(msecs)d           Millisecond portion of the creation time
		%(relativeCreated)d Time in milliseconds when the LogRecord was created,
												relative to the time the logging module was loaded
												(typically at application startup time)
		%(thread)d          Thread ID (if available)
		%(message)s         The result of record.getMessage(), computed just as
												the record is emitted

		If a formatter sees that the format string includes "(asctime)s", the
		creation time is formatted into the LogRecord's asctime attribute.  To
		allow flexibility in formatting dates, Formatters are initialized with
		a format string for the message as a whole, and a separate format string
		for date/time.  The date/time format string should be in time.strftime
		format.  The default value for the message format is "%(message)s".
		The default date/time format is ISO8601.

		The formatter uses a class attribute, "converter", to indicate how to
		convert a time from seconds to a tuple. By default, the value of
		"converter" is "time.localtime". If needed, a different converter (e.g.
		"time.gmtime") can be set on an individual formatter instance, or
		the class attribute changed to affect all formatter instances.

Filters

    When level-based filtering is insufficient, a Filter can be called by
    a Logger or Handler to decide if a LogRecord should be output. Loggers
    and Handlers can have multiple filters installed, and any one of them
    can veto a LogRecord being output.

        class Filter:
            def filter(self, record):
                """
                Return a value indicating true if the record is to
                be processed. Possibly modify the record, if deemed
                appropriate by the filter."""

    The default behaviour allows a Filter to be initialized with a Logger
    name. This will only allow through events which are generated using the
    named logger or any of its children.  For example, a filter initialized
    with "A.B" will allow events logged by loggers "A.B", "A.B.C", "A.B.C.D",
    "A.B.D" etc. but not "A.BB", "B.A.B" etc. If initialized with the empty
    string, all events are passed by the Filter. This filter behaviour is
    useful when it is desired to focus attention on one particular area of
    an application; the focus can be changed simply by changing a filter
    attached to the root logger.

		There are many examples of Filters provided in [6].

Remote Logging

		Through mechanisms such as SocketHandler and DatagramHandler, logging
		messages can be sent to remote machines. Since the remote machines have
		no access to the Python environment of the machine which generated the
		message, this means that certain information needs to be extracted from
		the environment at logging time and sent along with the message. The
		information currently in this category is the pathname and line number
		of the source file where the logging call was issued, the thread id of
		the caller, and exception traceback information.


Configuration

    The main benefit of a logging system like this is that one can
    control how much and what logging output one gets from an
    application without changing that application's source code. Therefore,
    although configuration can be performed through the logging API, it
    must also be possible to change the logging configuration without
    changing an application at all. For long-running programs like Zope,
    it should be possible to change the logging configuration while the
    program is running.

    Configuration includes the following:

        - What logging level a logger or handler should be interested in.
        - What handlers should be attached to which loggers.
        - What filters should be attached to which handlers and loggers.
        - Specifying attributes specific to certain handlers and filters.

    In general each application will have its own requirements for how
    a user may configure logging output.  However, each application will
    specify the required configuration to the logging system through a
    standard mechanism.

		The most simple configuration is that of a single handler, writing to
		stderr, attached to the root logger. This configuration is set up
		by calling the basicConfig() function once the logging module has been
		imported.

			def basicConfig(): ...

    For more sophisticated configurations, this PEP makes no specific
    proposals, for the following reasons:

    	-	A specific proposal may be seen as prescriptive.
    	- Without the benefit of wide practical experience in the Python
    		community, there is no way to know whether any given configuration
    		approach is a good one.  That practice can't really come until the
    		logging module is used, and that means until *after* Python 2.3 has
    		shipped.
    	- There is a likelihood that different types of applications may
    		require different configuration approaches, so that no "one size fits
    		all".

    The reference implementation [6] has a working configuration file format,
    implemented for the purpose of proving the concept and suggesting one
    possible alternative. It may be that separate extension modules, not part
    of the core Python distribution, are created for logging configuration and
    log viewing, supplemental handlers and other features which are not of
    interest to the bulk of the community.


Thread Safety

		The logging system should support thread-safe operation without any
		special action needing to be taken by its users.

Module-Level Functions

    To support use of the logging mechanism in short scripts and small
    applications, module-level functions debug(), info(), warn(), error(),
    critical() and exception() are provided. These work in the same way
    as the correspondingly named methods of Logger - in fact they delegate
    to the corresponding methods on the root logger. A further convenience
    provided by these functions is that if no configuration has been done,
    basicConfig() is automatically called.

		At application exit, all handlers can be flushed by calling the function

				def shutdown():	...

		This will flush and close all handlers.

Implementation

    The reference implementation is Vinay Sajip's logging module [6].

Packaging

    The reference implementation is implemented as a single module. This
    offers the simplest interface - all users have to do is "import logging"
    and they are in a position to use all the functionality available.

References

    [1] java.util.logging
        http://java.sun.com/j2se/1.4/docs/guide/util/logging/

    [2] log4j: a Java logging package
        http://jakarta.apache.org/log4j/docs/index.html

    [3] Protomatter's Syslog
        http://protomatter.sourceforge.net/1.1.6/index.html
        http://protomatter.sourceforge.net/1.1.6/javadoc/com/protomatter/syslog/syslog-whitepaper.html

    [4] MAL mentions his mx.Log logging module:
        http://mail.python.org/pipermail/python-dev/2002-February/019767.html

    [5] Jeff Bauer's Mr. Creosote
        http://starship.python.net/crew/jbauer/creosote/

		[6] Vinay Sajip's logging module.
				http://www.red-dove.com/python_logging.html

Copyright

    This document has been placed in the public domain.



Local Variables:
mode: indented-text
indent-tabs-mode: nil
fill-column: 70
End:
