Another look at python's logging library

Python's logging library is a mixed bag. The code was clearly written in a pre-python3 and pre-pep8 era, so it has a lot of sharp edges. It also feels like there is much more complexity than would be needed for such a simple task. But this library also offers a lot of flexibility for advanced users as well as shortcuts for simple use cases. So let's take a look.

Creating log records

Typically you would create log records like this:

import logging

logger = logging.getLogger(__name__)

def myfunc():
    logger.error('something went wrong')

First you create a logger instance with the name of the current module (e.g. 'myproject.utils'). Loggers form a hierarchy that is derived from their names. For example, the logger 'myproject.utils' would propagate to 'myproject'. The root logger is available as logging.root. You do not have to use the module name, but it is a good default.

Once you have a logger you can create log records. There is a method for each log level (debug(), info(), warn(), error(), and critical()). Each of these will also extract some information from the call stack, e.g. the path and line of the place where it was triggered. There is also exception() which is the same as error() but will also capture the stack trace.

For very simple cases, you can skip the logger and use shortcut functions instead, e.g. logging.error(). These will use the root logger. If handlers have not yet been configured (see next section), these shortcuts will also make sure that log records are written to stderr.

Configuring handlers

Log records are sent to stderr by default. In production settings you usually want something more involved, so you have to configure handlers.

logging provides many useful handlers such as StreamHandler to write to stderr or SMTPHandler to send mails. Many more handlers are available from third party packages.

Handlers have some options. First, you may want to filter which log records are even considered for a given handler. You can set a minimum level or add a custom Filter object for more complex conditions. After that, you need to convert the log record to a string. The default format is %(levelname)s:%(name)s:%(message)s. But you can customize it using a Formatter object.

Unfortunately, there are multiple different options to configure handlers. Let's first create the necessary objects manually:

import logging
from logging.handlers import SMTPHandler

formatter = logging.Formatter(
    '%(asctime)s %(levelname)-8s %(name)s %(message)s'
)

logging.root.setLevel(logging.NOTSET)

streamhandler = logging.StreamHandler()
streamhandler.setLevel(logging.INFO)
streamhandler.setFormatter(formatter)
logging.root.addHandler(streamhandler)

smtphandler = SMTPHandler(
    'localhost',
    'me@localhost',
    'you@localhost',
    'new log message',
)
smtphandler.setLevel(logging.ERROR)
smtphandler.setFormatter(formatter)
logging.root.addHandler(smtphandler)

The second option is to use the shortcut function basicConfig() which has all kinds of defaults. A simple call to basicConfig() will configure a stream handler. You can do more with it, but it breaks down pretty quickly. For the example above, basicConfig() doesn't really have any benefits.

The third option is to use a dictionary:

import logging.config

logging.config.dictConfig({
    'version': 1,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)-8s %(name)s %(message)s'
        },
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'level': 'INFO',
            'formatter': 'default',
        },
        'mail': {
            'class': 'logging.handlers.SMTPHandler',
            'mailhost': 'localhost',
            'fromaddr': 'me@localhost',
            'toaddrs': 'you@localhost',
            'subject': 'new log message',
            'level': 'ERROR',
            'formatter': 'default',
        },
    },
    'root': {
        'handlers': ['console', 'mail'],
        'level': 'NOTSET',
    },
})

The main benefit of this version is that you can encode this dictionary as a JSON string, so it can be used with all kinds of setups.

The final option is to use logging.config.listen() to start a TCP server that can receive configuration in JSON format. I am not sure why you would want to do that and I find it rather strange that this is included in the standard library.

Attaching handlers to specific loggers

In most cases you will want to attach your handlers to the root logger and then filter records there. But you can also attach handlers to different loggers. Consider this example:

logging.config.dictConfig({
    'version': 1,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
        'audit-file': {
            'class': 'logging.FileHandler',
            'filename': 'audit.log',
        },
    },
    'loggers': {
        'audit': {
            'handlers': ['audit-file'],
            'propagate': False,
        },
    },
    'root': {
        'handlers': ['console'],
        'level': 'NOTSET',
    },
})

This way, log records from the "audit" namespace will be logged to a file instead of stderr.

Recommendations

logging has lots of flexibility, so much so that it is sometimes hard to know how to do simple things. So here are some recommendations:

• Attach handlers to the root logger.
• Use dictConfig(), as it gives you full control and can be used in any setup.
• It is theoretically possible to set a minimum level for both loggers and handlers. I can't think of any case where a minimum level on a logger is useful, so you should stick to using it on handlers.
• All loggers and handlers are initialized with no minimum level (i.e. NOTSET). The only exception is the root logger which has a minimum level of WARNING. To avoid confusion, I strongly recommend to reset that to NOTSET.

Wishful thinking

With that said, there are some things in logging that I wish were different:

• All handlers should accept level and formatter as keyword arguments. The current way to construct them is just awkward.
• The root logger should have the NOTSET level.
• The default format should include the time. A log message without the time is pretty much useless. Sometimes your logging pipeline will attach a time automatically (e.g. journald). But for all other cases you basically have to configure a custom formatter.
• Python has accumulated a bunch of string formatting syntaxes, and consequently logging offers different formatting styles (%, {, and $). This is just silly. Everyone should just use the default style.
• logging.config.listen() has no place in the standard library and should be removed.
• This is a bigger thing, but I am just not sold on the whole hierarchy idea. It adds a lot of complexity without a tangible benefit because you could achieve the same thing with filters.

Conclusion

The right logging configuration is crucial. If your logs get lost you cannot debug issues. And if you do not get notified about errors, you might not even realize what is going on. I personally have wasted too much time with complex logging configurations. So it was high time to take a deeper look into this. I hope my recommendations will prove to be helpful.