python-peps/peps/pep-0282.rst

PEP: 282
Title: A Logging System
Author: Vinay Sajip <vinay_sajip at red-dove.com>,
        Trent Mick <trentm@activestate.com>
Status: Final
Type: Standards Track
Content-Type: text/x-rst
Created: 04-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:

* java.util.logging in JDK 1.4 (a.k.a. JSR047) [1]_
* log4j [2]_
* the Syslog package from the Protomatter project [3]_
* 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.

.. code-block:: python

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

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

.. code-block:: python 

    --------- 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")
    -----------------------------------------------------

.. code-block:: console 

    $ 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:

.. code-block:: text 

    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 its ``__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]_.


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:
       https://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.
       https://old.red-dove.com/python_logging.html


Copyright
=========

This document has been placed in the public domain.