Python Logging Traps
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:
- interpolation overhead is skipped if info level is not enabled
- encoding problems will not raise an exception (they’ll be logged instead)
- tools like Sentry will be able to aggregate log messages intelligently
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.