Python logging tutorial

by hcvst

The Python standard library’s logging module is flexible and easy to use, yet its documentation left me initially confused. I wrote this brief tutorial as a quick reference for my own benefit and hopefully yours.

Basics

" plane0.py - Plane simulation "

import logging

def fly():
    logging.debug('All systems operational')
    logging.info('Airspeed 300 knots')
    logging.warn('Low on fuel')
    logging.error('No fuel. Trying to glide.')
    logging.critical('Glide attempt failed. About to crash.')

This is how I used the logging module in the past. By invoking the functions  directly on module level, I get to use the default (‘the root’) logger. Let’s try to fly from the Python
shell.

>>> import plane0
>>> plane0.fly()
WARNING:root:Low on fuel
ERROR:root:No fuel. Trying to glide.
CRITICAL:root:Glide attempt failed. About to crash.

As you can see the messages are emitted by ‘root’, but what happened to the debug and info message? The RootLogger’s debug level is set to WARN by default. Let’s quickly confirm that and then change it.

>>> import logging
>>> logging.root
<logging.RootLogger instance at 0xb7cc50cc>
>>> logging.root.level == logging.WARN
True
>>> logging.root.setLevel(logging.DEBUG)
>>> plane0.fly()
DEBUG:root:All systems operational
INFO:root:Airspeed 300 knots
WARNING:root:Low on fuel
ERROR:root:No fuel. Trying to glide.
CRITICAL:root:Glide attempt failed. About to crash.

Using your own logger instead of root

" plane1.py - "

import logging

log = logging.getLogger('plane1')
log.setLevel(logging.ERROR)

def fly():
    log.debug('All systems operational')
    log.info('Airspeed 300 knots')
    log.warn('Low on fuel')
    log.error('No fuel. Trying to glide.')
    log.critical('Glide attempt failed. About to crash.')

>>> import plane1
>>> plane1.fly()
No handlers could be found for logger "plane1"
>>> import logging
>>> plane1.log.addHandler(logging.StreamHandler())
>>> plane1.fly()
No fuel. Trying to glide.
Glide attempt failed. About to crash.

Oops. It looks like no handler had been defined for our custom logger. We rectify this by adding a StreamHandler, which by default prints to stderr. There’re also handlers to write to a file (FileHandler), to an email address (SMTPHandler) and many more (see the module logging.handlers).

Now, let’s change the log level from ERROR, as set by us in the plane1.py module above, to WARN.

>>> l = logging.getLogger('plane1')
>>> l.setLevel(logging.WARN)
>>> plane1.fly()
Low on fuel
No fuel. Trying to glide.
Glide attempt failed. About to crash.

This time I did not poke at the module’s log instance directly, instead I asked logging for a reference using the getLogger function (the same function I used in plane1.py to create our custom logger in the first place. If no logger by that name exists it is created, else a reference is returned.)

Log format

Did you notice that the root logger prefixed all output by something like CRITICAL:root:… whereas our logger did not? Let’s change that. But first let’s try to find the root logger’s format string from a fresh Python shell.

>>> import logging
>>> logging.root
<logging.RootLogger instance at 0xb7ce906c>
>>> logging.root.handlers
[]
>>> logging.warn('No Handlers?')
WARNING:root:No Handlers?
>>> logging.root.handlers
[<logging.StreamHandler instance at 0xb7e2b08c>]
>>> logging.root.handlers[0]
<logging.StreamHandler instance at 0xb7e2b08c>
>>> logging.root.handlers[0].formatter
<logging.Formatter instance at 0xb7e2b12c>
>>> logging.root.handlers[0].formatter._fmt
'%(levelname)s:%(name)s:%(message)s'

Ah, so a Formatter instance is an attribute of a Handler instance which in turn is associated with a logger (in this case root’s) instance!  Let’s update our module to use a custom formatter.

" plane2.py - "

import logging

log = logging.getLogger('plane1')
log.setLevel(logging.ERROR)
formatter = logging.Formatter('[%(levelname)s] %(message)s')
handler = logging.StreamHandler()
handler.setFormatter(formatter)
log.addHandler(handler)

def fly():
    log.debug('All systems operational')
    log.info('Airspeed 300 knots')
    log.warn('Low on fuel')
    log.error('No fuel. Trying to glide.')
    log.critical('Glide attempt failed. About to crash.')

>>> import plane2
>>> plane2.fly()
[ERROR] No fuel. Trying to glide.
[CRITICAL] Glide attempt failed. About to crash.that

So, a logger can have one or more handlers and each handler exactly one formatter.

So far we set the log level always directly for the logger instance itself. In the following example , let’s log all messages to a file and in addition log messages with a severity level of ERROR or higher to stderr.

" plane3.py - "

import logging

log = logging.getLogger('plane1')
log.setLevel(logging.DEBUG)
formatter = logging.Formatter('[%(levelname)s] %(message)s')
handler_stream = logging.StreamHandler()
handler_stream.setFormatter(formatter)
handler_stream.setLevel(logging.ERROR)
log.addHandler(handler_stream)
handler_file = logging.FileHandler('plane.log')
handler_file.setFormatter(formatter)
log.addHandler(handler_file)

def fly():
    log.debug('All systems operational')
    log.info('Airspeed 300 knots')
    log.warn('Low on fuel')
    log.error('No fuel. Trying to glide.')
    log.critical('Glide attempt failed. About to crash.')

>>> import plane3
>>> plane3.fly()
[ERROR] No fuel. Trying to glide.
[CRITICAL] Glide attempt failed. About to crash.
>>> print(open('plane.log').read())
[DEBUG] All systems operational
[INFO] Airspeed 300 knots
[WARNING] Low on fuel
[ERROR] No fuel. Trying to glide.
[CRITICAL] Glide attempt failed. About to crash.

Log hierarchies

Source Wikipedia

Finally let’s take a quick look at logger hierarchies.  Like a file system, or Python modules, loggers can be arranged in a hierarchy, a tree with the root logger at its root. As for Python modules ‘.’ dots separate hierarchy levels.

In the last example, let’s add an emergency subsystem to the plane simulation. It could have been placed into a separate module but for simplicity it’s included. Also, we’re not going to define any handlers in the module but leave that to the module clients, since we cannot  anticipate how users might want to handle logs.

"plane4.py"

import logging

log = logging.getLogger('plane')
sublog = logging.getLogger('plane.ejectionseat')

def fly():
    log.debug('All systems operational')
    log.info('Airspeed 300 knots')
    log.warn('Low on fuel')
    log.error('No fuel. Trying to glide.')
    log.critical('Glide attempt failed. About to crash.')
    eject()

def eject():
    sublog.debug('Ejected at 100 ft')
    sublog.info('Parachute deployed')
    sublog.info('Safely landed')

>>> import plane4
>>> plane4.fly()
No handlers could be found for logger "plane"
>>> import logging
>>> l = logging.getLogger('plane')
>>> l.addHandler(logging.StreamHandler())
>>> plane4.fly()
Low on fuel
No fuel. Trying to glide.
Glide attempt failed. About to crash.
>>> l.setLevel(logging.DEBUG)
>>> plane4.fly()
All systems operational
Airspeed 300 knots
Low on fuel
No fuel. Trying to glide.
Glide attempt failed. About to crash.
Ejected at 100 ft
Parachute deployed
Safely landed
>>> l.setLevel(logging.ERROR)
>>> plane4.fly()
No fuel. Trying to glide.
Glide attempt failed. About to crash.
>>> lsub = logging.getLogger('plane.ejectionseat')
>>> lsub.setLevel(logging.DEBUG)
>>> plane4.fly()
No fuel. Trying to glide.
Glide attempt failed. About to crash.
Ejected at 100 ft
Parachute deployed
Safely landed

If you examine the Python shell session above you can see how the sub-logger’s output initially conforms to the settings of its parent. Once we have a reference to the sub-logger though we can configure it independently.

Thanks for reading and please let me know your comments, suggestions and corrections below.

handler_stream.setFormatter(formatter)