Logging

Log is important. Log is necessary. But strangely, it’s covered very little to none at all in school. Heck, it took me years to finally use log in my app. First time I truly learn about log is when I’m using web framework. Because it’s simply hard to debug if you don’t understand logging.

Logging in Python is simple, truly simple. But unfortunately, no one can answer my stupid beginner questions. So I’m stuck at the first step.

If we use log extensively, our log is so comprehensive to the point that make it hard to trace. All the log is there and we must hunt out what we need that time. It’s different from using print command, where we usually delete the command after debug is finished. Though often times I usually forgot to delete them.

Of course, there is nothing wrong by using print, but if we are using py.test we got a problem. We don’t see the result of print. This is where logging comes to the rescue.

First step to make our log easier to read is to make them specific. We do this by creating a logger with name. Say you want to create a log for module baz in foo.bar package.

# baz.py file in foo.bar package.
import logging


def fn():
  logger = logging.getLogger(__name__)
  logger.debug('Init')
  return None

Because we want to catch the debug log, we simply need to set the log level. Say you want to see the log when you test the baz module.

# tests/bar.py
import logging
from bar.bar import baz


def test():
  logger = logging.getLogger('foo.bar.baz')
  logger.setLevel(logging.DEBUG)
  # or you can do this to spew out all log
  # logging.basicConfig(level=logging.DEBUG)

  assert baz.fn() == 'x'

If your test fail, you will see the stderr output.

Library

It is recommended that a library logger should be attached with NullHandler.

# baz.py file in foo.bar package.
import logging


logging.getLogger(__name__).addHandler(logging.NullHandler())


def fn():
  logger = logging.getLogger(__name__)
  logger.debug('Init')
  return None

Due to NullHandler, even if the test fail we won’t see the stderr output anymore. In this case we need to add a handler.

# tests/bar.py
import logging
from bar.bar import baz


def test():
  logger = logging.getLogger('foo.bar.baz')
  logger.addHandler(logging.StreamHandler())
  logger.setLevel(logging.DEBUG)
  # or you can do this to spew out all log
  # logging.basicConfig(level=logging.DEBUG)

  assert baz.fn() == 'x'

Like before, we will see the log if the test fail.

String Formatting

Use logger.info('Info: %s', arg) rather than logger.info('Info: {}'.format(arg)). Because the former will only interpolate the string if arg is emitted. Or in other words, the former is lazy loading while the later is eager loading.

Capturing Exception

During exception, especially unexpected error, it’s better to show the traceback. Logging module make it easy to do: logger.error('Something broke', exc_info=True).