How To Add Custom Attributes in Python Logging

Logging is essential for any software system. Using logs, you can troubleshoot a wide range of issues, including debugging an application bug, security defect, system slowness, etc. In this article, we will discuss how to use Python logging effectively using custom attributes.

Python Logging

Before we delve in, I briefly want to explain a basic Python logging module with an example.

#!/opt/bb/bin/python3.7

import logging
import sys

root = logging.getLogger()
root.setLevel(logging.DEBUG)
std_out_logger = logging.StreamHandler(sys.stdout)
std_out_logger.setLevel(logging.INFO)
std_out_formatter = logging.Formatter("%(levelname)s - %(asctime)s  %(message)s")
std_out_logger.setFormatter(std_out_formatter)
root.addHandler(std_out_logger)

logging.info("I love Dzone!")

The above example prints the following when executed:

INFO - 2024-03-09 19:49:07,734  I love Dzone!

In the example above, we are creating the root logger and the logging format for log messages. On line 6, logging.getLogger() returns the logger if already created; if not, it goes one level above the hierarchy and returns the parent logger. We define our own StreamHandler to print the log message at the console.

Whenever we log messages, it is essential to log the basic attributes of the LogRecord. On line 10, we define the basic format that includes level name, time in string format, and the actual message itself. The handler thus created is set at the root logger level.

We could use any pre-defined log attribute name and the format from the LogRecord library. However, let's say you want to print some additional attributes like contextId, a custom logging adapter to the rescue.

Logging Adapter

class MyLoggingAdapter(logging.LoggerAdapter):

    def __init__(self, logger):
        logging.LoggerAdapter.__init__(self, logger=logger, extra={})

    def process(self, msg, kwargs):
        return msg, kwargs

We create our own version of Logging Adapter and pass "extra" parameters as a dictionary for the formatter.

ContextId Filter

import contextvars

class ContextIdFilter(logging.Filter):

    context_id = contextvars.ContextVar('context_id', default='')

    def filter(self, record):
        # add a new UUID to the context.
        req_id = str(uuid.uuid4())
        if not self.context_id.get():
            self.context_id.set(req_id)
        record.context_id = self.context_id.get()
        return True

We create our own filter that extends the logging filter, which returns True if the specified log record should be logged. We simply add our parameter to the log record and return True always, thus adding our unique id to the record. In our example above, a unique id is generated for every new context. For an existing context, we return already stored contextId from the contextVars.

Custom Logger

import logging

root = logging.getLogger()
root.setLevel(logging.DEBUG)
std_out_logger = logging.StreamHandler(sys.stdout)
std_out_logger.setLevel(logging.INFO)
std_out_formatter = logging.Formatter("%(levelname)s - %(asctime)s ContextId:%(context_id)s  %(message)s")
std_out_logger.setFormatter(std_out_formatter)
root.addHandler(std_out_logger)
root.addFilter(ContextIdFilter())

adapter = MyLoggingAdapter(root)

adapter.info("I love Dzone!")
adapter.info("this is my custom logger")
adapter.info("Exiting the application")

Now let's put it together in our logger file. Add the contextId filter to the root. Please note that we are using our own adapter in place of logging wherever we need to log the message.

Running the code above prints the following message:

INFO - 2024-04-20 23:54:59,839 ContextId:c10af4e9-6ea4-4cdf-9743-ea24d0febab6 I love Dzone!
INFO - 2024-04-20 23:54:59,842 ContextId:c10af4e9-6ea4-4cdf-9743-ea24d0febab6 this is my custom logger
INFO - 2024-04-20 23:54:59,843 ContextId:c10af4e9-6ea4-4cdf-9743-ea24d0febab6 Exiting the application

By setting root.propagate = False, events logged to this logger will be passed to the handlers of higher logging, aka parent logging class.

Conclusion

Python does not provide a built-in option to add custom parameters in logging. Instead, we create a wrapper logger on top of the Python root logger and print our custom parameters. This would be helpful at the time of debugging request-specific issues.