Getting Along with Python

Log messages with the logging module

Bugs are easier to find when your programs log messages which tell the story of what they are doing. But some ways of doing this are better than others.

What you should not do is scatter print statements throughout code you need to debug, then remove them later. It creates work every time and frequently breaks things. It’s no better to clutter up your code with many lines like if whatever: print, since the output still all goes to sys.stdout, which means wading through noise to find important messages.

It’s better to log messages using Python’s standard, builtin logging module. Then your implementation code can generate as many messages as you might ever need to understand what it’s doing, while the actual handling of those messages can be configured from outside that implementation. In other words, the logging module decouples the generation of messages from the way they are handled.

Unfortunately, the logging module is complex and its subtle pitfalls take a while to learn. This document tries to provide a shortcut around that which should help you understand the module and use it effectively without having to learn as much the hard way.

Note

You may notice that function and method names like basicConfig aren’t PEP 8 compliant. Unfortunately, a few old parts of Python’s standard library have such problems and aren’t likely to be changed soon. In your own new code, please Apply community style conventions.

Overview

Any sane use of logging has two clearly separated sides.

The ‘producer’ side generates log messages from implementation or library code. This only requires getting a logger object, and logging messages by calling methods on that logger object which pass the messages to be logged.

The ‘consumer’ side handles the generated log messages. This handling is to be set up by an application like a command line script, GUI app, or web app. It involves configuring one or more loggers to handle messages, specifying things like how the logs are to be formatted and what is to be done with the formatted lines. To ensure all messages are handled as specified, this has to be done early, like parsing command lines and config files. Normally this should happen in one place, and this is where the app may allow users to tweak the logging configuration.

To maintain your sanity and that of your users, it’s important that the producer and consumer sides stay separate. Library code and the ‘meat’ of your program should never configure logging, because this interferes with the ability of the app (and of the user) to configure logging. Libraries which need to log should set up loggers but leave them unconfigured.

Producing log messages

The first part of using logging is to generate log messages from inside your code. In order to generate messages, you should first obtain a logger object. Then use it to log messages at appropriate levels. The messages may also contain placeholders, to be substituted with passed values in the same way as string interpolation or string formatting.

Note

While this section covers a correct pattern for using the logging module to produce messages from code that should be logged, the messages are not visible by default when simply using the given example code. Keep reading the rest of the document to find out how to set that up. For information on why this happens, see Why no output?

Getting a logger

The right way to obtain a logger object is by calling logging.getLogger(name), where name is a human-interpretable string identifying the source of the log messages (for more on these names, see The logger hierarchy and Name loggers carefully).

import logging

logger = logging.getLogger("example")

Now we have a logger object named logger which can generate messages tagged with the logger name "example". Calling logging.getLogger("example") from anywhere in the same Python interpreter returns the same object.

Logging messages

Once you have a logger object, you can use it to log string messages at different log levels. The log level of a message indicates its importance. The higher the log level, the more important the message. This makes it possible to filter out messages which are less important in some situations.

import logging

logger = logging.getLogger("example")
logger.debug("Fine detail of little interest unless looking for bugs")
logger.info("Potentially useful information on normal functioning")
logger.warning("Concern or possible problem, but things are working")
logger.error("Real problem, but can't let an exception raise")
logger.critical("Something horrible, like an imminent crash")

This code logs several messages at different levels - all tagged with the logger name, "example".

What actually happens to these messages depends on how the logging system is configured by the app - more on this soon. Right now, we are only dealing with the code that generates log messages; that configuration should happen somewhere else.

You can also log exceptions which recently occurred using the exception() method on logger objects. This only works from inside an exception handler (that is, an except: clause).

try:
    hat_count = 42.0
    person_count = 0
    hats_per_person = hat_count / person_count
except ZeroDivisionError:
    # assume for some reason we can't let this exception raise,
    # so we at least want to leave a traceback in the log
    logger.exception("error while computing hats_per_person")

With a handler configured, you’ll see output like this:

ERROR:example:error while computing hats_per_person
Traceback (most recent call last):
  File "example.py", line 9, in <module>
    hats_per_person = hat_count / person_count
ZeroDivisionError: integer division or modulo by zero

As you can see, the message is logged like error(), but includes a multi-line traceback.

However, just using this code as given - while correct - will not give visible output. For details on why, see Why no output?

Messages with placeholders

If you want to include some variable values in your log messages, you can use placeholders of the same style as Python’s old string interpolation, and then pass the variables to render.

logger.error("invalid username %r", user.name)

After logging has been configured by an app, this might log the following line:

ERROR:example:invalid username 'sasha'

If you really want to use new-style str.format messages, you can just make the whole string and pass it to the logger method. Example:

logger.error("invalid username {0!r}".format(user.name))

Why no output?

The code we’ve looked at so far tells the right way to generate log messages. But if we just run it as-is, we don’t see anything but this message:

No handlers could be found for logger "example"

This means that the logger “example” is being used to generate messages before the logging system has been configured to tell it what to do with those messages. In other words, it is a warning that there are no consumers for what your logger is producing.

This is resolved by configuring the logging system to deal with the messages somehow. To do this correctly, you should first understand how log messages route through loggers and get handled by handlers.

(If you want to see output and don’t care about doing things wrong, a shortcut is to call logging.basicConfig, but it’s very easy to use this incorrectly. It is strongly recommended that you read the rest of this document to understand the system first, so you can appreciate what logging.basicConfig actually does.)

The logger hierarchy

Loggers are arranged in a hierarchy, or in other words, a tree. Every logger may have children, for which it is a parent. Messages “seen” by a logger are propagated to its parent by default. A logger’s parent-child relationships are defined by its name: a logger named a.b.c, as obtained with logging.getLogger("a.b.c"), is a child of the logger named "a.b". That logger’s parent is named "a" and its parent is the root logger, named "" (the empty string) and accessible with logging.getLogger("").

So a typical path taken by a message logged from a.b is first to a, and then the root logger.

In many cases, all messages are passed up to the root logger, and it is the root logger which is configured by the app at startup to handle all the messages logged inside the app. But all kinds of arrangements are possible.

Log levels

Log levels are a mechanism for filtering log messages by importance. By default, loggers pass everything they get to their parents. But if a logger has a current log level set on it, and it sees a message below that log level, the message is ignored.

If you have a logger and you want to set its level, call its setLevel method with one of the constants like logging.ERROR.

logger = logging.getLogger("a.b")
logger.setLevel(logging.ERROR)

This causes messages reaching the logger named "a.b" to be ignored if they have an importance level less than logging.ERROR (e.g., logging.WARNING, logging.INFO, logging.DEBUG). Such messages will not pass up to the parent logger and will not get handled.

Obviously the same thing can be done with the root logger. This example filters out messages reaching the root logger which are of a level below logging.INFO (e.g., logging.DEBUG).

logger = logging.getLogger("")
logger.setLevel(logging.INFO)

If all other loggers are passing messages to their parents, and the root logger is the only one with an attached handler, then setting the level of the root logger filters the log messages for the whole app. This is a common, simple way of managing how much log noise an app is generating.

Warning

Configuring the root logger (or any other shared logger) in a multi-threaded program must be done before other threads are started, or it is possible that multiple threads will do the same configuration, resulting in oddities like duplicated messages. You might let different threads make their own loggers, or avoid threading altogether if it is not necessary.

Consuming log messages

The second part of using logging is to configure loggers to handle messages that are routed through them. This is done by attaching handlers to those loggers. Different handlers store or send log messages in different ways.

Logging configuration should be done only from a whole program or script like a command line app, GUI app or web app. Preferably it should happen early during startup, in one place which allows users to override all logging settings.

Handlers

Handlers determine what is actually done with log messages. This can be any number of ways of saving, displaying or sending log messages. The messages a handler receives to handle are determined by which logger it is ‘attached’ to, the log level of that logger, and the log level of the handler.

To attach a handler to a logger, you must first make an instance of some Handler subclass, and then pass that handler to the logger’s addHandler method.

logger = logging.getLogger("example")
handler = logging.FileHandler("example.log")
logger.addHandler(handler)

A handler has its own level, which works like a logger’s but only affects the messages passing into this handler.

logger = logging.getLogger("example")
handler = logging.FileHandler("example.log")
handler.setLevel(logging.INFO)
logger.addHandler(handler)

The following gets a logger named "example", and attaches to it a handler which writes messages at or above level logging.INFO to a file arbitrarily named example.log. You might do this if you need to trace events in a particular component without interfering with whatever handlers are attached to the root logger.

import sys
import logging

logger = logging.getLogger("example")
logger.setLevel(logging.DEBUG)
handler = logging.FileHandler("example.log")
handler.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info("this goes into example.log using default formatting")
logger.debug("this doesn't go into example.log, it's below the handler level")

Here the handler itself is filtering out messages below logging.INFO. When the logger already filtered a message along the way, it won’t be handled by the handler even if it is above logging.INFO and so it will not be seen. (Remember that logging.DEBUG is even lower-level than logging.INFO.)

There are many handlers besides FileHandler. StreamHandler writes to a normal stream, like sys.stdout or sys.stderr. NullHandler literally does nothing, it’s for suppressing the warning about no handlers being found. There are also handlers which can do things like sending emails and more, and it is possible to write your own handlers if necessary. For more on these, see Python’s documentation on logging.handlers.

Formatters

Each handler has a Formatter determining how it formats the messages which go through it. To set a handler’s formatter, make an instance of Formatter and pass it to the handler’s setFormatter method.

This example explicitly attaches a StreamHandler with a custom formatter to the root logger. (You could do the same with a child logger, it doesn’t really matter except for which messages it affects.)

import logging

logger = logging.getLogger("")
handler = logging.StreamHandler()
formatter = logging.Formatter("%(name)s | %(levelname)s | %(message)s")
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.error("specially formatted error message")

From this you would expect the following output:

root | ERROR | specially formatted error message

The default format is something more like "%(levelname)s:%(name)s:%(message)s".

logging.basicConfig

logging.basicConfig is a function that can be used as a shortcut for setting up the root logger with a handler and a formatter. Like any method of configuring logging, it should not happen in library code but only in startup/initialization code of an app, and it should only be called once.

We can use it to achieve something very similar to the previous example:

logging.basicConfig(format="%(name)s | %(levelname)s | %(message)s")

This sets up the root logger by attaching a StreamHandler which has a Formatter containing the default format.

With other arguments, we can also set the root logger’s log level:

logging.basicConfig(level=logging.INFO)

This replaces the root logger’s default level of logging.WARNING with a lower level, so that you can see INFO messages and above (but not DEBUG messages, which are at a still lower level).

It’s also possible to use logging.basicConfig to use a stream other than sys.stderr, or set up a FileHandler instead. For more information on what it can do, see Python’s doc on logging.basicConfig. As the name indicates, this is only for basic configurations. If you need a more complex configuration, you will have to configure things yourself.

Good logging practices

Here are a few tips on how to use logging in an organized way that reduces unnecessary frustration.

Don’t log from the root logger

Avoid using the root logger to log messages. When you do this, all log messages come out of the same logger and cannot be independently controlled. For example, users cannot enable detailed debug messages from one component without being drowned in similarly detailed messages from every component.

Don’t log using the shortcut functions

Commonly-used functions like logging.error or logging.debug are also to be avoided in most cases.

Don’t configure loggers from library code

Configuring loggers inside a library prevents users of the library from easily configuring the loggers according to their needs. So library code (or any code intended for reuse in multiple places) can create and use loggers, but should never configure them. If you are writing a library which logs messages, just setup the loggers and leave it to other code to configure those loggers as it needs to. This applies even if you are the only user of your library code.

Ideally, there should be only one place in any application where logging is configured, and that place should be in the outermost layer of the app, maybe near where it parses command lines and config files. This configuration needs to happen early anyway to allow logs to be emitted. Keeping logger configuration out of the inner implementation of your app lets you change the app’s behavior more easily, touching fewer components, and it makes it easier to reuse that implementation in multiple ways if that will ever be necessary.

Name loggers carefully

You should normally log through a logger other than the root logger, e.g. using logging.getLogger(name). This raises the issue of how many loggers to make, and what names they should have.

The name of a logger should say something to human readers, like where the log messages come from. For example, if your project is named example and uses one logger, it would be logical to name that logger "example".

A useful trick is for each module to use a logger named __name__, as obtained by logging.getLogger(__name__). Python’s special variable __name__ normally contains the name of the current module, as in "mypackage" or "mypackage.subpackage", so each module ends up with its own logger. This also means that the logger for mypackage.subpackage is a child of the logger for mypackage, propagating messages up to it.

If you write multiple components, consider whether each one should use a different logger. That lets users of your components arrange different handling for log messages from the different components.

On the other hand, you don’t need to go crazy making many loggers. For example, it may be overcomplicated and unhelpful to make a different named logger for every single message, function and class. But it’s up to you.

If it is very likely that users will want to be able to configure logging for multiple related components at once, give those loggers a common parent. For example, if loggers named "bar" and "baz" should be treated the same in one situation but differently in another situation, you could instead use loggers named "foo.bar" and "foo.baz" so that they share the parent named "foo". For example, this lets users turn off all loggers under foo at once while leaving the root logger intact, or see more detail from foo.bar but less from foo.baz.

Avoid RotatingFileHandler

Log rotation is really useful to have. Using a RotatingFileHandler from Python is one way to do this. If you are working on a project where everyone else prefers this method, then so be it.

But when someone wants to deploy code that is hard-coded to use RotatingFileHandler internally, it takes away their ability to externally manage the logs according to their own log rotation policy (implemented by tools like logrotate), unless they edit the code. Many sysadmins do not necessarily want or know how to fix Python code, and it is not something which should ever need to be done near the time of deployment.

It might be slightly better to let a RotatingFileHandler be specified in a logging config - at least this is not editing Python code. This is a compromise which still allows logrotate to be used. But logrotate is probably a better solution wherever it is available.

Don’t log inside signal handlers

Logging inside signal handlers that are set using the signal module is not safe. See the logging doc’s section on thread safety.

Don’t log in performance-critical loops and functions

Definitely don’t avoid logging prematurely because of a concern about performance. It’s pretty cheap. But if something is happening hundreds of thousands of times, it is worth considering whether logging a line each time is productive, or whether it is just going to create a lot of log data and slow things down without casting a lot of light on anything important.

Further Steps

Be sure to learn about Use a debugger as another part of civilized debugging.

If you are a heavy user of logging, you may also want to read up on ways to let your application take logging configuration from a file, apply logging Filters to do fancier filtering than you can do just based on the log level, or send logs to a remote log service. It would also be good to learn about logrotate and structured logging.