ONLamp.com    
 Published on ONLamp.com (http://www.onlamp.com/)
 See this if you're having trouble printing code examples

Python Standard Logging

by Jeremy Jones
06/02/2005

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.

Loggers

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() 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:

Related Reading

Python in a Nutshell
By Alex Martelli

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.

Handlers

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:

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:

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

Formatters

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:

"%(asctime)s - %(levelname)s - %(message)s"

Configuring Logging

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:

import logging

#create logger
logger = logging.getLogger("simple_example")
logger.setLevel(logging.DEBUG)
#create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
#create formatter
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - 
   %(message)s")
#add formatter to ch
ch.setFormatter(formatter)
#add ch to logger
logger.addHandler(ch)

#"application" code
logger.debug("debug message")
logger.info("info message")
logger.warn("warn message")
logger.error("error message")
logger.critical("critical message")

Running this module from the command line produces the following output:

jmjones@bean:~/logging $ python simple_logging_module.py
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message
2005-03-19 15:10:26,620 - simple_example - INFO - info message
2005-03-19 15:10:26,695 - simple_example - WARNING - warn message
2005-03-19 15:10:26,697 - simple_example - ERROR - error message
2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message

The following Python module creates a logger, handler, and formatter nearly identical to those in the example listed above, with the only difference being the names of the objects:

import logging
import logging.config

logging.config.fileConfig("logging.conf")

#create logger
logger = logging.getLogger("simpleExample")

#"application" code
logger.debug("debug message")
logger.info("info message")
logger.warn("warn message")
logger.error("error message")
logger.critical("critical message")

Here is the logging.conf file:

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

The output is nearly identical to that of the non-config-file-based example:

jmjones@bean:~/logging $ python simple_logging_config.py
2005-03-19 15:38:55,977 - simpleExample - DEBUG - debug message
2005-03-19 15:38:55,979 - simpleExample - INFO - info message
2005-03-19 15:38:56,054 - simpleExample - WARNING - warn message
2005-03-19 15:38:56,055 - simpleExample - ERROR - error message
2005-03-19 15:38:56,130 - simpleExample - CRITICAL - critical message

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:

#!/usr/bin/env python

import logging
import logging.config
import time
import os

#specify logging config file
logging.config.fileConfig("logging.conf")

#create and start listener on port 9999
t = logging.config.listen(9999)
t.start()

#create logger
logger = logging.getLogger("simpleExample")

#watch for existence of file named "f"
#loop through the code while this file exists
while os.path.isfile('f'):
    logger.debug("debug message")
    logger.info("info message")
    logger.warn("warn message")
    logger.error("error message")
    logger.critical("critical message")
    time.sleep(5)

#cleanup
logging.config.stopListening()
t.join()

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:

#!/usr/bin/env python

import socket
import sys
import struct

HOST = 'localhost'
PORT = 9999
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print "connecting..."
s.connect((HOST, PORT))
print "connected..."
data_to_send = open(sys.argv[1], "r").read()
print "sending length..."
s.send(struct.pack(">L", len(data_to_send)))
print "sending data..."
s.send(data_to_send)
print "closing..."
s.close()

Example Usage

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.

Multiple handlers and formatters

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:

#!/usr/bin/env python

import logging

#create logger
logger = logging.getLogger("simple_example")
logger.setLevel(logging.DEBUG)
#create console handler and set level to error
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
#create file handler and set level to debug
fh = logging.FileHandler("spam.log")
fh.setLevel(logging.DEBUG)
#create formatter
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - 
   %(message)s")
#add formatter to ch and fh
ch.setFormatter(formatter)
fh.setFormatter(formatter)
#add ch and fh to logger
logger.addHandler(ch)
logger.addHandler(fh)

#"application" code
logger.debug("debug message")
logger.info("info message")
logger.warn("warn message")
logger.error("error message")
logger.critical("critical message")

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.

Using logging in multiple modules

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:

#!/usr/bin/env python

import logging
import auxiliary_module

#create logger with "spam_application"
logger = logging.getLogger("spam_application")
logger.setLevel(logging.DEBUG)
#create file handler and set level to debug
fh = logging.FileHandler("spam.log")
fh.setLevel(logging.DEBUG)
#create console handler and set level to error
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
#create formatter
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - 
   %(message)s")
#add formatter to fh
fh.setFormatter(formatter)
#add formatter to ch
ch.setFormatter(formatter)
#add fh to logger
logger.addHandler(fh)
#add ch to logger
logger.addHandler(ch)

logger.info("creating an instance of auxiliary_module.Auxiliary")
a = auxiliary_module.Auxiliary()
logger.info("created an instance of auxiliary_module.Auxiliary")
logger.info("calling auxiliary_module.Auxiliary.do_something")
a.do_something()
logger.info("finished auxiliary_module.Auxiliary.do_something")
logger.info("calling auxiliary_module.some_function()")
auxiliary_module.some_function()
logger.info("done with auxiliary_module.some_function()")

Here is the auxiliary module:

#!/usr/bin/env python

import logging

#create logger
module_logger = logging.getLogger("spam_application.auxiliary")


class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger("spam_application.auxiliary.Auxiliary")
        self.logger.info("creating an instance of Auxiliary")
    def do_something(self):
        self.logger.info("doing something")
        a = 1 + 1
        self.logger.info("done doing something")

def some_function():
    module_logger.info("received a call to \"some_function\"")

The output looks like this:

2005-03-23 23:47:11,663 - spam_application - INFO - 
   creating an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO - 
   creating an instance of Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO - 
   created an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO - 
   calling auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO - 
   doing something
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO - 
   done doing something
2005-03-23 23:47:11,670 - spam_application - INFO - 
   finished auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO - 
   calling auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO - 
   received a call to "some_function"
2005-03-23 23:47:11,673 - spam_application - INFO - 
   done with auxiliary_module.some_function()

Conclusion

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.

Return to the Python DevCenter.

Copyright © 2009 O'Reilly Media, Inc.