A Python decorator which 'saved' logging

I write this post to illustrate the beauty of Python decorators. Decorators are one of those beasts in Python which are very powerful and elegant. It makes your code more readable and at the same time avoids a lot of code duplication. The following use case of decorators happened while I was working on one of my Python projects at work.

Application Logging

In the application, logging was enabled like so:

import logging


def initLogging() :

    logging.basicConfig(
                    filename='/var/log/app.log',
                    level=logging.DEBUG,
                    format="%(asctime)-15s %(filename)s:%(lineno)-4d %(funcName)s %(levelname)s:%(message)s"
        )

The code above would write the logs of this application into the specified file in the specified format. After this, I could start logging for various levels using logging.debug(), logging.info(), logging.warning(), logging.error() etc. However, these logging methods were wrapped inside helper methods like so:

def LOG_DEBUG(msg):   
    logging.debug(msg)

def LOG_INFO(msg):   
    logging.info(msg)

def LOG_ERROR(msg):   
    logging.error(msg)

def LOG_WARN(msg):   
    logging.warning(msg)

Then throughout the application, the wrapper methods were used. Now we have a problem with these wrapper methods.

Problem with wrapping up logging method invocations

Since we have used wrappers for the logging methods, the logs reported in the log file would always show the function name and line number corresponding to the wrapper methods. This is not what we intended. We needed the function name and line number of the code where the wrapper invocation was used.

Decorator to the rescue

We could avoid this problem by replacing all the wrapper function calls with the actual logging method calls. This would be tedious and we would be sprinkling the logging methods calls everywhere. It just looks so nice to use the wrapper methods in the code than using the logging method calls.

The inspect module in Python provides methods to inspect the stack frame. We could make use of this to get the actual function name and line number by coding the inspect module stuff inside all of our wrapper methods. This could lead to a lot of duplicate code and it is certainly not elegant.

We still want the inspect module stuff, but can we do better? This I wrote the following decorator:

def caller_prefix(func):

"""

This decorator function modifies log message
to include the actual calling function name and line number
in the message.

"""

    @wraps(func)    
    def wrapper(*args, **kwargs):        
        callerframerecord = inspect.stack()[1] # 1: represents line at the caller            
        frame = callerframerecord[0]            
        info = inspect.getframeinfo(frame)

        # Prefixes the function name and line number to the actual message(args[0])            
        # args[1:] - concatenate to make sure we don't lose it after manipulating args            
        args = (f'{info.function}:{info.lineno}: {args[0]}', ) + args[1:]

        func(*args, **kwargs)

    return wrapper

and then decorated all the wrapper method with this decorator like so:

@caller_prefix
def LOG_DEBUG(msg) :   
    logging.debug(msg)

@caller_prefix
def LOG_INFO(msg) :
    logging.info(msg)

@caller_prefix
def LOG_ERROR(msg) :
    logging.error(msg)

@caller_prefix
def LOG_WARN(msg) :
    logging.warning(msg)

In the above code caller_prefix is the decorator which magically modifies the wrapper methods. It uses the inspect module and modifies the message to include the actual function name and the line number which we intended to log. Look how elegantly the decorators changed the behavior of wrapper methods without code duplication or extra function calls.

Conclusion

Python decorators are very useful. It might be a little mind-boggling at first to grasp the decorator concepts. However, when we get the gist of them, we will be able to write some very cool stuff. Python decorator is the magic wand every python programmer would like to add to his toolkit.

If you would like to study Python decorators, I would recommend the following RealPython tutorial.

That's it for now, until next time.