Recently I faced an exciting challenge. I needed to create a robust logging system integrated with an external API. One of the requirements was to have specific contextual data logged whenever it was available. The main issue was that a lot of it was spread across the whole application, nested within different functions.
The most trivial approach of passing down necessary objects through the functions would bloat the code unnecessarily. I started to think about how to leverage context managers to collect the data. After several iterations, together with the team, I came up with an elegant solution, which gave us extra fluff we could use in the app. Let me show you the code and explain the reasoning behind it. Ready? Let’s move on!
Setting up logging context handler
First, we will create a data store for our context manager. It needs to have three capabilities:
- we need to be able to add more contextual data to it
- it should return a specific attribute value by its name
- it should be able to remove contextual data when no longer needed.
To achieve this, we will create a stack with dictionaries as their elements. The dictionaries will contain a set of contextual data to be used in logging. Let’s see how it looks:
class LoggingContextHandler:
def __init__(self):
self.attributes = deque([{}])
def add(self, **new_context_vars):
old_context = self.attributes[0]
new_context = {**old_context, **new_context_vars}
self.attributes.appendleft(new_context)
def get(self, key):
return self.attributes[0].get(key)
def remove(self):
self.attributes.popleft()
def __str__(self):
return str(self.attributes)
Let’s take a deeper look at the add method because that’s where the magic happens.
Whenever we add new data to the context, add clones the dictionary from the top of the stack and updates it with newly added content. This way, we won’t need to iterate over the whole stack to get an attribute hidden deep within it.
I mentioned a context manager a couple of times, but where is it? Let me fix that right away!
Creating context manager
There’s nothing fancy, just a simple function. Whatever you use as the argument will be pushed to the handler defined above. After the successful execution of the wrapped code, the manager will drop the data from the context.
logging_context_handler = LoggingContextHandler()
@contextmanager
def logging_context(**kwargs):
logging_context_handler.add(**kwargs)
yield
logging_context_handler.remove()
Adjusting log records with filters
Now that we have the data source and a way to manage it, we can add the data to the log records. The recommended way is to use filters for that, so let’s create one and attach it to a logging handler.
class ContextFilter(logging.Filter):
def __init__(self):
super(ContextFilter, self).__init__()
def filter(self, record):
record.store = logging_context_handler.get("store")
record.client = logging_context_handler.get("client")
record.item = logging_context_handler.get("item")
return True
logger = logging.getLogger()
context_filter = ContextFilter()
logger.addFilter(context_filter)
Such a filter will add attributes from logging context to each log record. Of course, we can go crazy with what we’d like to do with that. But for the sake of simplicity, let’s build a formatter that displays our newly added attributes in a logger of our choice.
Creating a formatter
We don’t need to build anything robust. For our purposes, a simple setFormatter function call would be enough.
format_string = "[%(store)s | %(client)s | %(item)s]: %(message)s"
stdout_formatter = logging.Formatter(format_string)
stdout_handler = logging.StreamHandler(sys.stdout)
stdout_handler.setFormatter(stdout_formatter)
logger.addHandler(stdout_handler)
Let’s see how it all works
With the setup done, we can now check how it’s all used. Let me show you a simple app as an example.
Imagine that we have a grocery store, and we want to track to whom we sell the goods through logging. We have two clients, Jim and Tim, each with his shopping list. Let’s build a code that will allow us to sell goods to them.
from logs import logger
from logs.logging_context import logging_context
clients = {"Jim": ["potatoes", "tomatoes"], "Tim": ["bread", "eggs", "milk"]}
def sell_goods(shopping_list):
for item in shopping_list:
with logging_context(item=item):
logger.info("Sold 1 item.")
with logging_context(store="Hannah's Grocery Store"):
for client, shopping_list in clients.items():
with logging_context(client=client):
sell_goods(shopping_list)
Note that the only argument passed to sell_goods function is a shopping list since there’s no need to add anything else.
After you run the script, it will produce such an output:
[Hannah's Grocery Store | Jim | potatoes]: Sold 1 item.
[Hannah's Grocery Store | Jim | tomatoes]: Sold 1 item.
[Hannah's Grocery Store | Tim | bread]: Sold 1 item.
[Hannah's Grocery Store | Tim | eggs]: Sold 1 item.
[Hannah's Grocery Store | Tim | milk]: Sold 1 item.
As you can see, all data stored in context get displayed in logs.
We can take this even further. Let’s say that the sell_goods function also checks if an item is available and throws an error when there’ none. If we logged the exception, we could then see that next clients didn’t buy eggs, because the store ran out of them.
Beware of the base logger!
One critical thing to mention is that you should create a separate logger for your app.
Once, I mistakenly added the handlers to the base logger, and then I saw external libraries throwing errors at me. After a short investigation, it turned out that they were all trying to add extra attributes to log records without having access to them. Save yourself from frustration, and don’t do this, please.
I hope that you had a good read and have another neat solution to add to your toolbox!
If you’d like to download the project to check its capabilities immediately, here’s a link to the repository: https://github.com/kampikd/logging-context-python
Feel free to pull the code and play around with it!
Many thanks to Piotr Kotnis for plenty of thought-provoking ideas 💙. Without his help and insights, this solution would not be as refined as it is.
Top comments (0)