logging.exception()

I almost feel stupid writing about a functionality I just discovered but that has been around since Python 2.3: logging.exception(). A very cool feature with a sprinkle of magic.

Logging errors

Sooner or later we all get to the point where we need to log things that go wrong. I recently had to compile human readable data into a less friendly but more compact version.

def compile_data(data_type, data):
    compiler = get_compiler(data_type)
    try:
        compiled = compiler(data)
        return compiled
    except Exception as err:
        log.error("Error compiling data: %s", err)

In this example we catch any exceptions that might stem from the compiler. But sometimes the error message is not very useful. Here, how should we interpret this message?

2013-02-10 18:24:03,436 [ERROR] Error compiling data: 'operator'

After debugging we realize that what really happened was KeyError: 'operator'. This information would have been useful in the first place, so let's make the error message a little more useful by logging the name of the class that was raised:

    ...
    except Exception as err:
        log.error("Error compiling data: %s, %s", err.__class__.__name__, err)

Better. But we still don't know what caused the problem and we finally admit that having the traceback would ideally give us better insights on what broke.

Before...

This is when I start messing around with the traceback module or sys.exc_info()  in an attempt to nicely log the traceback.

But this was before.

Now.

Then I stumbled on Logger.exception(). It works like Logger.error() but it also appends the traceback for you for free. For it to work, Logger.exception() has to be called from within an except block (or it will log None). Also, it doesn't print the whole traceback from the very first frame but only the frames from your try/except block and down, a nice way to reduce verbosity especially if you use a framework where your code gets executed far down the stack.

    ...
    except Exception as err:
        log.exception("Error compiling data of type: %s, %s", data_type, data)

2013-02-10 18:24:03,436 [ERROR] Error compiling data of type: rule, {"some": "data"}
Traceback (most recent call last):
  File "compiler.py", line 66, in compile
    compiled = compiler(data)
  File "compiler.py", line 673, in rule_compiler
    return data['operator']
KeyError: 'operator'

Now we have a lot of information to debug our problem, but not too much (only lower frames). And you can still log a custom message that provides extra context.

Use wisely

Logging.exception() is very handy and after discovering it I wanted to log all tracebacks in my app. There are some times where it makes sense but I also realized that often times the information from the error message is sufficient. Logging tracebacks fills up your logs faster and you don't want to spam yourself, so use with care.