Python Standard Logging

Python 2.3 introduced the logging module to the Python standard
library. logging provides a standard interface for outputting
information from a running application. The classic example of a logging
mechanism is writing data to a text file, which is a plain old log file. While
the log file is likely the most common form of logging, the
logging module provides the ability to send information to
file-like objects, TCP and UDP sockets, email servers, the Unix syslog, the NT event
log, memory buffers, and HTTP servers in addition to "real" files.

The logging library takes a modular approach and offers the
several categories of components: loggers, handlers,
filters, and formatters. Loggers expose the interface that
application code directly uses. Handlers send the log records to the
appropriate destination. Filters provide a finer grained facility for
determining which log records to send on to a handler. Formatters specify the
layout of the resultant log record.

Logger objects have a threefold job. First, they expose several methods to
application code so that applications can log messages at runtime. Second,
logger objects determine which log messages to act upon based upon severity
(the default filtering facility) or filter objects. Third, logger objects pass
along relevant log messages to all interested log handlers.

The most widely used methods on logger objects fall into two categories:
configuration and message sending.

The configuration methods are:

setLevel(level)

addFilter(filter)

removeFilter(filter)

addHandler(handler)

removeHandler(handler)

setLevel() specifies the lowest-severity log message a logger
will handle, where debug is the lowest built-in severity level and
critical is the highest built-in severity. For example, if the
severity level is info, the logger will handle
only info, warning, error, and
critical messages and will ignore debug messages.

addFilter() and removeFilter() add and remove
filter objects from the logger object. This article does not address
filters.

With the logger object configured, the following methods create log
messages:

debug(), info(), warning(),
error(), and critical() all create log records with a
message of log_message and a level that corresponds to their
respective method names. log_message is actually a format string,
which may contain the standard string substitution syntax of %s, %d,
%f, and so on. *args is a list
of objects that correspond with the substitution fields in
log_message. With regard to **kwargs, the logging
methods care only about a keyword of exc_info and use it to
determine whether to log exception information.

exception() creates a log message similar to
error(). The difference is that exception() dumps a
stack trace along with it. Call this method only from an exception handler.

log() takes a log level as an explicit argument. This is a
little more verbose for logging messages than using the log level convenience
methods listed above, but this is how to log at custom log levels.

logging.getLogger([name]) returns a reference to a logger
instance with a name of name if a name is provided, or
root if not. The names are period-separated (.)
hierarchical structures. Multiple calls to logging.getLogger()
with the same name will return a reference to the same logger object. Loggers
that are further down in the hierarchical list are children of loggers higher up in the list. For example, given a logger with a name of
foo, loggers with names of foo.bar,
foo.bar.baz, and foo.bam are all children of
foo. Child loggers propagate messages up to their parent loggers.
Because of this, it is unnecessary to define and configure all the loggers an
application uses. It is sufficient to configure a top-level logger and create
child loggers as needed.

Handler objects are responsible for dispatching the appropriate log messages
(based on the log messages' severity) to the handler's specified destination.
Logger objects can add zero or more handler objects to themselves with an
addHandler() method. As an example scenario, an application may
want to send all log messages to a log file, all log messages of
error or higher to stdout, and all messages of
critical to an email address. This scenario requires three
individual handlers where each hander is responsible for sending messages of a
specific severity to a specific location.

The standard library includes the following handlers:

StreamHandler

FileHandler

RotatingFileHandler

TimedRotatingFileHandler

SocketHandler

DatagramHandler

SysLogHandler

NTEventLogHandler

SMTPHandler

MemoryHandler

HTTPHandler

This article uses only StreamHandler and
FileHandler in its examples.

There are very few methods in a handler for application developers to
concern themselves with. The only handler methods that seem relevant for
application developers who are using the built-in handler objects (that is, not creating custom handlers) are the following configuration methods:

setLevel(level)

setFormatter(formatter)

addFilter(filter)

removeFilter(filter)

The setLevel() method, just as in logger objects, specifies the
lowest severity that will be dispatched to the appropriate destination. Why are
there two setLevel() methods? The level set in the logger
determines which severity of messages it will pass to its handlers. The level
set in each handler determines which messages that handler will send on.
setFormatter() selects a Formatter object for this handler to use.
addFilter() and removeFilter() respectively configure
and deconfigure filter objects on handlers.

Application code should not directly instantiate and use handlers. Instead,
the logging.Handler class is a base class that defines the
interface that all Handlers should have and establishes some
default behavior that child classes can use (or override).

Formatter objects configure the final order, structure, and contents of the
log message. Unlike the base logging.Handler class, application
code may instantiate formatter classes, although you could likely subclass the
formatter if your application needs special behavior. The constructor takes two
optional arguments: a message format string and a date format string. If there
is no message format string, the default is to use the raw message. If there is
no date format string, the default date format is:

%Y-%m-%d %H:%M:%S

with the milliseconds tacked on at the end.

The message format string uses %(<dictionary key>)s
styled string substitution. Here is the Formatter class's
docstring, which describes the valid substitution strings and what they
mean:

%(name)s Name of the logger (logging channel)
%(levelno)s Numeric logging level for the message (DEBUG, INFO,
WARNING, ERROR, CRITICAL)
%(levelname)s Text logging level for the message ("DEBUG", "INFO",
"WARNING", "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 (name portion of filename)
%(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)
%(process)d Process ID (if available)
%(message)s The result of record.getMessage(), computed just as
the record is emitted

The following message format string will log the time in a
human-readable format, the severity of the message, and the contents of the message, in that order:

Programmers can configure logging either by creating loggers, handlers, and
formatters explicitly in a main module with the configuration methods listed
above (using Python code), or by creating a logging config file. The following
code is an example of configuring a very simple logger, a console handler, and
a simple formatter in a Python module:

The config file approach has a few advantages over the Python code approach.
The first is the separation of configuration and code. The second is the ability of noncoders to easily modify the logging properties. The third is the
really cool listen() method, which causes the application to listen
on a socket for new configurations--and will update configurations at runtime
without forcing you to restart the application!

Here is a slight modification of the previous config file-based script:

That was simple enough. Unfortunately, figuring out what format the config
file needs to be took some investigation. The only useful information that I
found in the Python Standard Library Reference documentation was in the logging
configuration section under the listen() method:

Logging configurations will be sent as a file suitable for
processing by fileConfig().

Pushing a filename did not work. Pushing the contents of a config file did
not work. I had to dig into the source a little. The docstring for the logging
socket server's handle() method is:

Handle a request.
Each request is expected to be a 4-byte length,
followed by the config file. Uses fileConfig() to do the
grunt work.

This struck me as a bit odd. Does that mean you can send lengths only for
config files of up to 9,999 bytes? Converting the length of the config file to a
string did not work either. I looked farther down in the source code of the
handle() method. Aaahh. It does a struct.unpack(),
so the socket expects the first 4 bytes to be packed binary data. I tried
it this way and it worked. The following snippet of code sends the contents of
the file named on the command line to localhost:9999:

This article contains several examples of simple usage of the
logging module. Two additional examples deserve special
attention: using multiple handlers or formatters and using logging in
multimodule Python applications.

Loggers are plain Python objects. The addHandler() method has
no minimum or maximum quota for the number of handlers you may add. Sometimes it will be beneficial for an application to log all messages of all severities to a
text file while simultaneously logging errors or above to the console. To set
this up, simply configure the appropriate handlers. The logging calls in the
application code will remain unchanged. Here is a slight modification to the
previous simple module-based configuration example:

Notice that the "application" code did not change between the single-handler
example and this one. All that changed was the addition and
configuration of a new handler named fh.

The ability to create new handlers with higher- or lower-severity filters can
be very helpful when writing and testing an application. How many times have I
written a horde of print statements in a section of code as I was
trying to hammer something out, only to comment it out later? A better
approach, which also opens the door for later troubleshooting, is to use
logger.debug instead of print. Unlike the
print statements, which you will have to delete or comment out
later, the logger.debug statements can remain intact in the source
code and remain dormant until you need them again. At that time, the only
change that needs to happen is to modify the severity level of the logger
and/or handler to debug.

I mentioned above that multiple calls to
logging.getLogger('someLogger') return a reference to the same
logger object. This is true not only within the same module, but also across modules
as long as it is in the same Python interpreter process. It is
true for references to the same object; additionally, application code can define and
configure a parent logger in one module and create (but not configure) a child
logger in a separate module, and all logger calls to the child will pass up to
the parent. Here is a main module:

logging was a great addition to the standard library. It
provides application developers a simple, single interface for outputting
information from a running application. On the very simple end, it can write
information to a standard log file. On the more advanced end, it can write the
same information to a socket--and it can do both without having to rewrite a
single line of application code or even restart the process. So the next
time you start to put a bunch of print statements in your code to
debug something, consider using logging--specifically,
logger.debug(). You won't be disappointed.

Jeremy Jones
is a software engineer who works for Predictix. His weapon of choice is Python.