Python logging tutorial

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)
Advertisements
This entry was posted in python. Bookmark the permalink.

10 Responses to Python logging tutorial

  1. Lucas says:

    Thanks a lot, you’ve clarified my understanding about the logging module.

  2. quasipedia says:

    Easy to follow, very clear, thanks for the effort! 🙂

  3. GTR says:

    YOU have explained beautifully the the python logging tutorial.
    it’s clear my basic understanding.
    Thanks AAALOT!

  4. J. Heasly says:

    Cleanest explanation I’ve found. Thanks very much!

  5. EM says:

    Very helpful. Thanks!

  6. solamon says:

    Good Work Man Your post make me help Thank so much

  7. t3 says:

    the tutorial is very good. I can understand the logging library now.

  8. babar says:

    Thanks, this is a very decent tutorial on logging.

  9. Richard Bowden says:

    good article, one small amendment.

    log = logging.getLogger(‘plane’)
    sublog = logging.getLogger(‘plane.ejectionseat’)

    can be done as the following

    sublog = log.getChild(‘ejectionseat’)

    this has the same effect but lets the logging module take care of the hierarchy.

    Hope that helps

  10. hagay onn says:

    nice tutorial, been fun and easy to read, 10x and keep-up!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s