Python Logging Traps

24 Nov 2014 · By Simon Weber

Python's logging framework is powerful, but gives you plenty of ways to shoot yourself in the foot. To make matters worse, logging mistakes are subtle and slip through code review easily.

In my time at Venmo, I've seen logging mistakes cause everything from unneeded debugging to application crashes. Here are the most common culprits:

Manual Interpolation

Bad:

logger.info("My data: %s" % some_data)
# or, equivalently
logger.info("My data: {}".format(some_data))

Good:

logger.info("My data: %s", some_data)

This pushes the interpolation off to the logging framework:

Pylint will detect this antipattern as W1201 and W1202.

logger.error(...e) in exception handlers

Bad:

try:
    ...
except FooException as e:
    logger.error("Uh oh! Error: %s", e)

Good:

try:
    ...
except FooException:
    logger.exception("Uh oh!")

Formatting an exception throws away the traceback, which you usually want for debugging. logger.exception is a helper that calls logger.error but also logs the traceback.

Implicitly encoding unicode data

Bad:

checkmark = '√'.decode('utf-8')
logger.info("My data: %s", checkmark)

Good:

logger.info("My data: %r", checkmark)

Using %s with a unicode string will cause it to be encoded, which will cause an EncodingError unless your default encoding is utf-8. Using %r will format the unicode in \u-escaped repr format instead.