iSharkFly-Open
/
python-peps
mirror of https://github.com/python/peps.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Vinay's update, with lots of reformatting by Barry.

This commit is contained in:
Barry Warsaw 2002-07-08 16:50:43 +00:00
parent 664cf2aec9
commit ff7fbb6b19
1 changed files with 407 additions and 237 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

624
pep-0282.txt
View File

@ -2,7 +2,7 @@ PEP: 282
Title: A Logging System
Version: $Revision$
Last-Modified: $Date$
Author: vinay_sajip@red-dove.com (Vinay Sajip)
Author: vinay_sajip at red-dove.com (Vinay Sajip)
Status: Draft
Type: Standards Track
Created: 4-Feb-2002
@ -15,11 +15,11 @@ Abstract
This PEP describes a proposed logging package for Python's
standard library.
Basically the system involves the user creating one or more
logging 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
trivial ones.
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
@ -44,89 +44,96 @@ Motivation
Influences
This proposal was put together after having somewhat studied the
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]
These two systems are *very* similar.
o the Syslog package from the Protomatter project [3]
o MAL's mx.Log package [4]
This proposal will basically look like java.util.logging with a
smattering of log4j.
Simple Example
This shows a very simple example of how the logging package can be
used to generate simple logging output on stdout.
used to generate simple logging output on stderr.
--------- mymodule.py -------------------------------
import logging
log = logging.getLogger("MyModule")
def doit():
log.debug("doin' stuff")
# do stuff ...
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("start my app")
log.info("Starting my app")
try:
mymodule.doit()
mymodule.doIt()
except Exception, e:
log.error("There was a problem doin' stuff.")
log.info("end my app")
log.exception("There was a problem.")
log.info("Ending my app")
-----------------------------------------------------
> python myapp.py
0 [myapp.py:4] INFO MyApp - start my app
36 [mymodule.py:5] DEBUG MyModule - doin' stuff
51 [myapp.py:9] INFO MyApp - end my app
^^ ^^^^^^^^^^^^ ^^^^ ^^^^^ ^^^^^^^^^^
| | | | `-- message
| | | `-- logging name/channel
| | `-- level
| `-- location
`-- time
% python myapp.py
NOTE: Not sure exactly what the default format will look like yet.
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
[Note: excerpts from Java Logging Overview. [5]]
Applications make logging calls on *Logger* objects. Loggers are
organized in a hierarchical namespace and child Loggers may
inherit some logging properties from their parents in the
namespace.
organized in a hierarchical namespace and child Loggers inherit
some logging properties from their parents in the namespace.
Notes on 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.
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 allocate *LogRecord* objects which are passed
to *Handler* objects for publication. 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 publish a LogRecord externally, a Handler can
(optionally) use a *Formatter* to localize and format the message
before publishing it to an I/O stream.
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 their parent Logger. But
Loggers may also be configured to ignore Handlers higher up the
tree.
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
@ -137,6 +144,17 @@ Control Flow
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
@ -146,51 +164,167 @@ Levels
INFO
WARN
ERROR
FATAL
ALL
CRITICAL
This is consistent with log4j and Protomatter's Syslog and not
with JSR047 which has a few more levels and some different names.
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.
Implementation-wise: these are just integer constants, to allow
simple comparison of importance. See "What Logging Levels?" below
for a debate on what standard levels should be defined.
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.
The *LogManager* maintains a 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".
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 main logging method is:
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, level, msg, *args):
"""Log 'msg % args' at logging level 'level'."""
def log(self, lvl, msg, *args, **kwargs):
"""Log 'str(msg) % args' at logging level 'lvl'."""
...
however convenience functions are defined for each logging level:
However, convenience functions are defined for each logging level:
def debug(self, msg, *args): ...
def info(self, msg, *args): ...
def warn(self, msg, *args): ...
def error(self, msg, *args): ...
def fatal(self, msg, *args): ...
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): ...
XXX How to defined a nice convenience function for logging an exception?
mx.Log has something like this, doesn't it?
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:
XXX What about a .raising() convenience function? How about:
class Logger:
def exception(self, msg, *args): ...
def raising(self, exception, level=ERROR): ...
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.
It would create a log message describing an exception that is
about to be raised. I don't like that 'level' is not first
when it *is* first for .log().
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
@ -201,18 +335,53 @@ Handlers
- StreamHandler: A handler for writing to a file-like object.
- FileHandler: A handler for writing to a single file or set
of rotating files.
More standard Handlers may be implemented if deemed desirable and
feasible. Other interesting candidates:
- SocketHandler: A handler for writing to remote TCP ports.
- CreosoteHandler: A handler for writing to UDP packets, for
- 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
(JSR047).
- SMTPHandler: Akin to log4j's SMTPAppender.
- SyslogHandler: Akin to log4j's SyslogAppender.
- NTEventLogHandler: Akin to log4j's NTEventLogAppender.
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
@ -221,192 +390,188 @@ Formatters
representation. A Handler may call its Formatter before writing a
record. The following core Formatters will be implemented:
- Formatter: Provide printf-like formatting, perhaps akin to
log4j's PatternAppender.
- Formatter: Provide printf-like formatting, using the % operator.
Other possible candidates for implementation:
- BufferingFormatter: Provide formatting for multiple
messages, with header and trailer formatting support.
- XMLFormatter: Serialize a LogRecord according to a specific
schema. Could copy the schema from JSR047's XMLFormatter or
log4j's XMLAppender.
- HTMLFormatter: Provide a simple HTML output of log
information. (See log4j's HTMLAppender.)
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
A Filter can be called by a Logger or Handler to decide if a
LogRecord should be logged.
JSR047 and log4j have slightly different filtering interfaces. The
former is simpler:
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 isLoggable(self):
"""Return a boolean."""
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 latter is modeled after Linux's ipchains (where Filter's can
be chained with each filter either 'DENY'ing, 'ACCEPT'ing, or
being 'NEUTRAL' on each check). I would probably favor to former
because it is simpler and I don't immediate see the need for the
latter.
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.
No filter implementations are currently proposed (other that the
do nothing base class) because I don't have enough experience to
know what kinds of filters would be common. Users can always
subclass Filter for their own purposes. Log4j includes a few
filters that might be interesting.
There are many examples of Filters provided in [6].
Configuration
Note: Configuration for the proposed logging system is currently
under-specified.
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.
Log4j and Syslog provide for configuration via an external XML
file. Log4j and JSR047 provide for configuration via Java
properties (similar to -D #define's to a C/C++ compiler). All
three provide for configuration via API calls.
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 should be interested in.
- 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.
- Defining the default configuration.
- XXX Add others.
- 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. One application
(e.g. distutils) may want to control logging levels via
'-q,--quiet,-v,--verbose' options to setup.py. Zope may want to
configure logging via certain environment variables
(e.g. 'STUPID_LOG_FILE' :). Komodo may want to configure logging
via its preferences system.
a user may configure logging output. However, each application
will specify the required configuration to the logging system
through a standard mechanism.
This PEP proposes to clearly document the API for configuring each
of the above listed configurable elements and to define a
reasonable default configuration. This PEP does not propose to
define a general XML or .ini file configuration schema and the
backend to parse it.
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.
It might, however, be worthwhile to define an abstraction of the
configuration API to allow the expressiveness of Syslog
configuration. Greg Wilson made this argument:
def basicConfig(): ...
In Protomatter [Syslog], you configure by saying "give me
everything that matches these channel+level combinations",
such as "server.error" and "database.*". The log4j "configure
by inheritance" model, on the other hand, is very clever, but
hard for non-programmers to manage without a GUI that
essentially reduces it to Protomatter's.
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.
Case Scenarios
Thread Safety
This section presents a few usage scenarios which will be used to
help decide how best to specify the logging API.
The logging system should support thread-safe operation without
any special action needing to be taken by its users.
(1) A short simple script.
This script does not have many lines. It does not heavily use
any third party modules (i.e. the only code doing any logging
would be the main script). Only one logging channel is really
needed and thus, the channel name is unnecessary. The user
doesn't want to bother with logging system configuration much.
Module-Level Functions
(2) Medium sized app with C extension module.
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.
Includes a few Python modules and a main script. Employs,
perhaps, a few logging channels. Includes a C extension
module which might want to make logging calls as well.
At application exit, all handlers can be flushed by calling the function
(3) Distutils.
def shutdown(): ...
A large number of Python packages/modules. Perhaps (but not
necessarily) a number of logging channels are used.
Specifically needs to facilitate the controlling verbosity
levels via simple command line options to 'setup.py'.
(4) Large, possibly multi-language, app. E.g. Zope or (my
experience) Komodo.
(I don't expect this logging system to deal with any
cross-language issues but it is something to think about.)
Many channels are used. Many developers involved. People
providing user support are possibly not the same people who
developed the application. Users should be able to generate
log files (i.e. configure logging) while reproducing a bug to
send back to developers.
This will flush and close all handlers.
Implementation
XXX Details to follow consensus that this proposal is a good idea.
The reference implementation is Vinay Sajip's logging module [6].
What Logging Levels?
Packaging
The following are the logging levels defined by the systems I looked at:
- log4j: DEBUG, INFO, WARN, ERROR, FATAL
- syslog: DEBUG, INFO, WARNING, ERROR, FATAL
- JSR047: FINEST, FINER, FINE, CONFIG, INFO, WARNING, SEVERE
- zLOG (used by Zope):
TRACE=-300 -- Trace messages
DEBUG=-200 -- Debugging messages
BLATHER=-100 -- Somebody shut this app up.
INFO=0 -- For things like startup and shutdown.
PROBLEM=100 -- This isn't causing any immediate problems, but
deserves attention.
WARNING=100 -- A wishy-washy alias for PROBLEM.
ERROR=200 -- This is going to have adverse effects.
PANIC=300 -- We're dead!
- mx.Log:
SYSTEM_DEBUG
SYSTEM_INFO
SYSTEM_UNIMPORTANT
SYSTEM_MESSAGE
SYSTEM_WARNING
SYSTEM_IMPORTANT
SYSTEM_CANCEL
SYSTEM_ERROR
SYSTEM_PANIC
SYSTEM_FATAL
The current proposal is to copy log4j. XXX I suppose I could see
adding zLOG's "TRACE" level, but I am not sure of the usefulness
of others.
Static Logging Methods (as per Syslog)?
Both zLOG and Syslog provide module-level logging functions rather
(or in addition to) logging methods on a created Logger object.
XXX Is this something that is deemed worth including?
Pros:
- It would make the simplest case shorter:
import logging
logging.error("Something is wrong")
instead of
import logging
log = logging.getLogger("")
log.error("Something is wrong")
Cons:
- It provides more than one way to do it.
- It encourages logging without a channel name, because this
mechanism would likely be implemented by implicitly logging
on the root (and nameless) logger of the hierarchy.
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
@ -427,6 +592,10 @@ References
[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.
@ -436,5 +605,6 @@ Copyright
Local Variables:
mode: indented-text
indent-tabs-mode: nil
sentence-end-double-space: t
fill-column: 70
End: