Taking Your Logging to the Next Level in Python

The Problem

In programming, if you are dedicated to the art of cleanliness then a function should do exactly one thing and no more.

Logging is a thing

This means that the conventional use of logging information to store for later auditing or troubleshooting violates the above idea that a function should only do one thing because the very act of logging is a mutation. And if we accept this premise, code that has logging inside of functions becomes increasingly bothersome.

Consider this example:

import logging

ARBITRARY_VALUE = 10


def some_function(item_list):
    item_len = len(item_list)
    logging.info("Received %s items in some_function" % item_len)

    filtered_items = [item for item in item_list if item.value > ARBITRARY_VALUE]

    items_removed = item_len - len(filtered_items)
    logging.info("Removed %s items" % items_removed)

    final_value = sum([item.value for item in filtered_items])
    logging.info("Returning %s" % final_value)

    return final_value

In my opinion, the function above is pretty ugly. I don’t know its actual purpose, I just made up some stuff. But look at the logging statements and the disruption it creates while reading. First of all, the overall size of the function is increased so the ease of reading has been diminished. Second, there is additional logic that’s been added to the function for the sole purpose of logging information. Without the logging statements, there would be some othes lines that could be removed. And finally, when reading the function there’s a context switch between English and code to understand what’s going on.

There Has to be a Better Way

And indeed, there might be. One way that I like to maintain that the functions I write do exactly one thing is to add decorators to functions. A well written decorator will not actually change what a function does, but it can add behavior that allows functions to be composed together that end up creating complex logic. If a decorator works properly, that means that it should be able to wrap a function with no risk. This means that if I have a decorator that can be generically applied, and it has test coverage, and if I have a function that I intend to decorate that already has test coverage, I should be able to apply the decorator to the function and not modify any of my tests. Depending on what the decorator does, however, there should probably be some testing around integration.

Now, apply this idea to logging. I want to write a decorator that can generically be applied to any function, and it just logs useful information extracted from the function. If I have this, I can then decorate any of my functions and maintain clean code. Someone reading my code can see the decorator and think “ok, logging is in place, cool” and then the contents of the function can be read without disruption or context switching, and those contents should be concise and expressive in and of themselves.

The Decorators

The above sounds nice (to me anyway), but there’s a big problem that needs to be solved: how can I log the locals of the function with a decorator? A decorator has no knowledge of what’s in scope in the function. My answer was to create a decorator that used a profiler to capture the frame in the call stack after the fact. From there, the the value of the frame’s variables in scope can be logged when the function exits.

import functools
import logging
import sys


class _LogTracer(object):
    def __init__(self):
        self._last_frame = None

    def tracer(self, frame, event, *extras):
        if event == 'return':
            self._last_frame = frame

    @property
    def last_frame(self):
        return self._last_frame


def log_locals_on_exit(fn):
    @functools.wraps(fn)
    def inner(*args, **kwargs):
        log_tracer = _LogTracer()
        sys.setprofile(log_tracer.tracer)
        try:
            result = fn(*args, **kwargs)
        finally:
            sys.setprofile(None)
        frame = log_tracer.last_frame

        _locals = {}
        for k, v in frame.f_locals.items():
            _locals[k] = repr(v)
        logging.info(_locals)
        return result
    return inner

A few things to consider with the above:

  • This is a barebones example of how one might log the local variables in a frame and can be expanded upon to add lots of additional meta-data
  • This is still problematic if one of your locals is, say, a list of one million items. Strategies need to be added for handling those cases
  • If you do the upfront work here, you should be able to generically apply this decorator anywhere.

I also didn’t actually do speed testing, but reflection is always slow, so it’s safe to assume that logging like this is expensive in terms of speed. This is just a trade-off to be aware of.

If you can implement this decorator, then it’s also trivial to implement another decorator that logs the parameters passed in to a function. But in that case, you don’t need to do all the introspection, you can just log the parameters passed in. So you can have a decorator that logs the state of the function when it starts and the state of the function when it exists. From there, you might add another decorator that combines those two functions:

def generic_log(fn):
    fn = log_locals_on_exit(fn)
    fn = log_entry(fn)
    return fn

And now we have a decorator that can be generically applied to any function! In addition to general cleanliness, this should also make it easy to add or remove logging with ease.

Logging Class Instances

So I didn’t just arbitrarily make up the above code just to do it, I applied the above concepts to production code at work. I thought it was awesome, but I quickly noticed a problem with how class instances were logged. It looked something like this:

'<__main__.SomeClass object at 0x10dc064d0>'

This was pretty useless for logging. The only valuable information here was the type of the instance. So I ended up creating a base class with a generic __repr__ method that all other classes in my repository inherited from. The return value was the class type and a unique UUID. The UUID was either a UUID that was already associated with the object (in the case that it was an entity that referenced a database row), or a UUID was generated by using the 16 byte md5 hash associated with a serialized version of the object (can be done a number of ways, I used the object’s __dict__ value).

This ended up working really well. First of all, one nice thing about UUID’s instead of auto increment integers is that each UUID is globally unique regardless of type. So if, for example, you wanted to search your logs using the ID of an object, you’ll never run into the clutter of multiple ID’s spread out across different class types.

Second, any instance of an object that referenced a row in the database always returned the same UUID. So you could grep for a particular UUID in your logs and you could see any associated object throughout time. Even objects that had no association with a database row returned a distinct UUID based on their class state. So you could even use UUID’s to traverse through logs to see that object again in another period in time when it was in an identical state.

The End

  • Chris Okasaki

    Here’s your next challenge. Right now, it looks like your logging will only log the top-level call to fn, but if fn calls itself recursively, then those inner calls will not be logged. So, your next challenge, should you choose to accept it, is to figure out how to (generically) have those inner calls be logged as well. [However, I’m not actually suggesting you make this change in production code.]

    • Scott Benedict Lobdell

      I’m impressed that you could read that so quickly. Nested function calls are stripped from the logging, but if you make a recursive call then the each function call should be decorated…I’ll verify