Skip to Main Content
Official App
Free – Google Play
FreshBooks is Loved by American Small Business Owners
FreshBooks is Loved by Canadian Small Business Owners
FreshBooks is Loved by Small Business Owners in the UK
Dev Blog

Logging actions with Python decorators Part I: Decorating logged functions

by Taavi on April 27/2010

are an elegant way to add common behaviour to your functions in a declarative way, communicating your intent but keeping the details out of your face. One good example of doing this is keeping a log of calls to a function. This is useful in debugging, but also in production, for example to send events to a message queue for additional processing (hello WebHooks).

At FreshBooks, we publish interesting events to our message broker (RabbitMQ) for a variety of consumers. Decoupling message production from message consumption allows us to add new producers or consumers without necessarily having to update the others. To make the logging code less repetitive and onerous, I wrote a decorator to log these interesting events. There are 2 major parts:

  • A decorator
  • A mixin

The mixin provides the actual logging functionality, while the decorator makes it a pleasure to use.

So, let’s start with the decorator. It lets you write (fictional) code like this to log the invoiceid in the return value by using objectid_attr:

@log_event('Create Invoice', objectid_attr='invoiceid')
def create_invoice(self, **attrs):
    # ...
    return invoice

That would log the ‘Create Invoice’ event and the returned invoice.invoiceid.

Or how about logging the invoiceid passed in as a function argument by using objectid_param:

@log_event('Delete Invoice', objectid_param='invoiceid')
def delete_invoice(self, invoiceid, **options):
    # ...
    return True

That would log the ‘Delete Invoice’ event and the invoiceid it was called with.

These examples are trivial, but the decorator remains simple even when you have multiple parameters and start changing their order.

So, how would we implement this decorator? Wait, let’s back up. What’s a decorator?

In Python, functions are , which means that you can pass them around as values to call later. Decorators are functions that take a function as an argument and return another function. The simplest example:

def before_after(f):
    def decorator():
    return decorator

Then we can define our decorated function like this:

def hello_world():
    print('Hello, world!')

Or, equivalently without using the @ operator:

# DO NOT DO THIS! This is the bad old way from before we had @!
def hello_world():
    print('Hello, world!')
hello_world = before_after(hello_world)

When we run it, we get:

# prints:
#  before
#  Hello, world!
#  after

That’s fancy, but we need to do something a little beefier. We’d like to tell the decorator what event to log. So we need a function that returns a function that takes a function and returns a function!

Let’s consider a decorator that changes the return value to be N times what it would be otherwise. So:

def add(a, b):
    return a + b
add(1,2) # returns (1 + 2) * 3 = 9
add(1,3) # returns (1 + 3) * 3 = 12

Python just wants some function after the @ sign. Whether we give it a function by name, or call a function that returns a function doesn’t matter. We could equivalently write the above by:

multiply_by_three = multiply_by(3)
def add(a, b):
    return a + b

We can imagine this sequence of add() to multiply_by_three() to multiply_by() visually:

Visual representation of multiply_by_three() and multiply_by() wrapping around the add() function

Of course, changing the return value like that makes addition look broken. With power comes responsibility!

So assuming we had a function called extract_param_by_name(), we could implement an event logging decorator like this:

from functools import wraps
def log_event(event, objectid_attr=None, objectid_param=None):
    """Decorator to send events to the event log
    You must pass in the event name, and may pass in some method of
    obtaining an objectid from the decorated function's parameters or
    return value.
    objectid_attr: The name of an attr on the return value, to be
        extracted via getattr().
    objectid_param: A string, specifies the name of the (kw)arg that
        should be the objectid.
    def wrap(f):
        def decorator(*args, **kwargs):
            self = extract_param_by_name(f, args, kwargs, 'self')
            value = f(*args, **kwargs)
            if objectid_attr is not None:
                event_objectids = getattr(value, objectid_attr)
            elif objectid_param is not None:
                event_objectids = extract_param_by_name(f, args, kwargs, objectid_param)
                event_objectids = None
            self._log_event(event, event_objectids)
            return value
        return decorator
    return wrap

We’ll look at extract_param_by_name() in part II of this post, and take a peek at what a mixin is in part III.