It’s a wrap(s)! Python Logging Decorators Improve Troubleshooting

A short journey into decorators and logging in Python.

DALL·E 3 Created Image

Have you ever wondered what arguments are passed when a function is called? Do you need help deciphering long error messages that are often confusing? Hopefully, we can fix that.

logging > print?

A common practice among developers is to use print statements frequently. However, as they become more familiar with logging and are reminded of its importance, they switch to using logging.info statements everywhere instead.

DALL·E 3 Created Image

This approach can result in longer code, though it allows for capturing more information. Fortunately, a simple solution can capture the desired information quite efficiently.

What’s the “simple” solution?

Decorators!

Python decorators are a powerful tool that allows developers to dynamically modify the behavior of functions or methods. They sound scary but aren’t too bad once you understand how they work.

Let’s see how they can be used with Python's logging module to improve the functionality and maintainability of code.

Here’s some code to implement a function to do this.

import logging
from functools import wraps

def logger(func):
    """
    A decorator function to log information about function calls and their results.
    """

    @wraps(func)
    def wrapper(*args, **kwargs):
        """
        The wrapper function that logs function calls and their results.
        """
        logging.info(f"Running {func.__name__} with args: {args}, kwargs: {kwargs}")
        try:
            result = func(*args, **kwargs)
            logging.info(f"Finished {func.__name__} with result: {result}")
        
        except Exception as e:
            logging.error(f"Error occurred in {func.__name__}: {e}")
            raise
        
        else:
            return result

    return wrapper

The wrapper function is a middle layer between the original function and the calling code. It logs information related to the function calls and their results, including any exceptions. When the decorated function is called, the wrapper function is invoked and calls the original function while logging relevant information. The decorator preserves the original function's metadata, ensuring introspection and debugging tools function correctly.

How does it work?

We can throw it on any function using the decorator.

@logger
def greet_user(name: str, greeting_type: str):
    if greeting_type == "short":
        return f"Hey, {name}!"
    elif greeting_type == "long":
        return f"Oh, hello there, {name}! How are you today?"
    else:
        raise ValueError("Invalid greeting type. Please choose 'short' or 'long'.")

Calling it is just like using any other function.

greet_user("Tyler", "short")
greet_user("Not Tyler", "short")
greet_user("Tyler", "BREAK")

Since my current session logs at the DEBUG level, I get back some helpful messages!

Logging messages from running the code.

Conclusion

Many topics are written on this subject, which can be very in-depth. I hope this serves as a gentle introduction and offers a starting point.

You should experiment with custom logging formats, integrate third-party logging libraries, or explore advanced decorator patterns beyond the scope of the article. Don’t hesitate to share your experiences or challenges while implementing logging decorators, as they might help others.

For some additional reading, check out these links:

functools - Higher-order functions and operations on callable objects

PEP 318 - Decorators for Functions and Methods