Logging actions with Python decorators Part I: Decorating logged functions
Python decorators 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
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 first class, 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(): print('before') f() print('after') return decorator
Then we can define our decorated function like this:
@before_after def hello_world(): print('Hello, world!')
Or, equivalently without using the
# 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:
hello_world() # 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:
@multiply_by(3) 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) @multiply_by_three def add(a, b): return a + b
We can imagine this sequence of
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): @wraps(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) else: 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.