Forem: Damian

Adding contextual data to Python logging

Damian — Mon, 26 Apr 2021 22:15:10 +0000

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.

Resources

https://docs.python.org/3/howto/logging-cookbook.html

What is Test Driven Development and why it is so awesome

Damian — Sat, 13 Jun 2020 19:46:42 +0000

At the beginning of my career as a Ruby developer, I used to work on a project that had barely any tests. This, combined with poor code quality, made the development of any new feature similar to a walk through a minefield — you never knew if your change is going to crash the app, even in a different place. Add my lack of knowledge at the time and a lot of stress, and you get a nightmare of experience for any beginner programmer.

Honestly, it was a miserable time. The project left such a vivid memory that it serves as an ongoing warning to avoid similar ones at all costs.

It’s been a while, and, luckily, I had a chance to learn proper practices, among them — Test-Driven Development. I can’t recall how many times it saved me from coding struggles in the course of my career.

Hence, knowing both sides of the coin, I want others to be able to kick-start their programming journey instead of making it a struggle.

Let me explain what’s the general idea behind TDD and give you a couple of reasons to give it a shot in your software development process. So, without further ado, let’s get started.

What is Test-Driven Development?

Test-Driven Development (or TDD) is a technique of software development in which you turn the requirements for a specific piece of code to a set of tests. Then, you write the code that should meet the requirements and make the tests pass. When you’re satisfied with the outcome, pick a new feature, and start all over. This perpetual process will result in a test suite created along with your main codebase.

Sounds easy, but why should you add an extra layer of code to maintain? There are plenty of reasons to do so:

1. It makes you think through your code better

When you plan a feature, it’s worth giving extra attention to good tests. There are plenty of things to consider when creating a new feature, among them performance, readability, etc. Still, no matter how your code is going to perform, you need to have it working correctly.

Tests put your focus on the expected results. After you prepare them, you can work on providing a piece of code that will meet the requirements.

Once you have it figured out, you can focus on code augmentation in a way that will let you achieve the same outcome, but in a better way. And if you ever get lost, there is a checkpoint you can always roll back to and start anew with a working piece of code.

2. You can reliably introduce changes to the code

In the early days of the project, it’s tempting to forfeit automated tests. I mean — why would you if you can grasp the whole concept? But what if the project grows and it becomes harder to remember every single bit of it?

Think of writing tests as an investment — you need to sacrifice some time now to save a lot of it in the future. If you forget about the tests at the very beginning, you will waste time and nerves while manually checking if everything works fine. And the bigger the app is, the worse this problem will become. On the other hand, a good test suite gives you the ability to check if the new changes are compatible with the rest of the codebase.

Moreover, it will save you plenty of time. Instead of clicking through the whole app you will run the test suite and wait for the results. If there’s an error, simply fix the code and you’re good to go.

3. Well-written tests can serve as documentation

Your code might behave in many different ways depending on the conditions. Good tests dispel all doubts by providing a clear description of the code’s behavior.

If you ever forget how a class works, you can come back to the test suite and check it. Moreover, it helps in the onboarding of new team members by being a single source of truth about the code.

I find this especially prominent when using Behavior-Driven Development frameworks like RSpec. To me, such tests have much more expressive syntax than regular ones.

I like the verbosity of tests created with BDD frameworks. It resembles natural language closer, hence making it easier to read even if you don’t know the programming language well. Still, either choice is fine, as long as you care for the quality of the tests. Just remember that better tests equal better documentation.

4. They can be easily automated

You can easily set up automated tools that help you keep good code quality by running tests. You can do it on various levels.

One common practice is to set up Continuous Integration (CI) tools. CI is a development practice in which developers frequently integrate their code into a shared repository. It intends to make the app as up-to-date as possible. Such an approach requires quality checks. Running tests on a dedicated server is one way to accomplish that. There are plenty of ready-made solutions in the market like TravisCI and CircleCI. You can also set up Jenkins on your server to run the tests for you.

And if that’s not enough, there’s plenty of tools you can run on your machine to monitor changes in your files and run appropriate tests. A couple of examples would be Guard for Ruby or Jest tests, where you append — watch flag to npm run test command.

I hope that I managed to show you the major benefits of using TDD. From my observations, it isn’t only another way to make your code better. Rather, it has become an industry standard and it happened for a reason. If you’re striving to make yourself a reliable developer, this is a way to go. Also, if you’re working on a project alone and have nobody else to check your code, or maybe have a worse day, automated tests can save you a lot of fuss by catching things you would have missed otherwise.