612 lines
22 KiB
Plaintext
612 lines
22 KiB
Plaintext
PEP: 282
|
||
Title: A Logging System
|
||
Version: $Revision$
|
||
Last-Modified: $Date$
|
||
Author: vinay_sajip at red-dove.com (Vinay Sajip),
|
||
trentm@activestate.com (Trent Mick)
|
||
Status: Final
|
||
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 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:
|
||
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
|
||
sentence-end-double-space: t
|
||
fill-column: 70
|
||
End:
|