Python logging with context

Python official documentation (logging cookbook) suggests two approaches to add contextual information to logs:

1. Using LoggerAdapters - for more details you can refer to pete lin`s answer.
2. Using Filters (and threadlocal variables) - A filter processes the record before it is being emitted. It's main purpose is to allow advanced and customized rules to reject log records (the filter method returns bool, which indices whether to emit the record). However, it also allows you to process the record - and add attributes based on whatever is required. For example, you can set the attributes based on a global threading.local variable.

Below is a Filter example that appends attributes from a global threading.local variable:

log_utils.py

import logging
import threading

log_context_data = threading.local()


class ThreadingLocalContextFilter(logging.Filter):
    """
    This is a filter which injects contextual information from `threading.local` (log_context_data) into the log.
    """
    def __init__(self, attributes: List[str]):
        super().__init__()
        self.attributes = attributes

    def filter(self, record):
        for a in self.attributes:
            setattr(record, a, getattr(log_context_data, a, 'default_value'))
        return True

log_context_data can be set when you start processing an account, and reset when you you're done. However, I recommend setting it using a context manager:

Also in log_utils.py:

class SessionContext(object):
    def __init__(self, logger, context: dict = None):
        self.logger = logger
        self.context: dict = context

    def __enter__(self):
        for key, val in self.context.items():
            setattr(log_context_data, key, val)
        return self

    def __exit__(self, et, ev, tb):
        for key in self.context.keys():
            delattr(log_context_data, key)

And a usage example, my_script.py:

root_logger = logging.getLogger()
handler = ...
handler.setFormatter(
    logging.Formatter('{name}: {levelname} {account} - {message}', style='{'))
handler.addFilter(ThreadingLocalContextFilter(['account']))
root_logger.addHandler(handler)
...
...
using SessionContext(logger=root_logger, context={'account': account}):
    ...
    ...
     

Notes:

1. Filter is only applied to the logger it is attached to. So if we attach it to a logging.getLogger('foo'), it won't affect logging.getLogger('foo.bar'). The solution is to attach the Filter to a Handler, rather than a logger.
2. ThreadingLocalContextFilter could've rejected records, if log_context_data doesn't contain the required attribute. This depends on what you need.

When to use what?

1. I'd recommend LoggerAdapters if you need to edit records for specific looger instances - in which case, it makes sense to instantiate an Adapter instead.
2. I'd recommend Filter if you want to edit all records that are handled by a specific Handler - including other modules and 3rd party packages. It is generally a cleaner approach in my opinion, since we only configure our logger in our entry code - and the rest of the code remains the same (no need to replace logger instances with adapter instances).

Forgive the self promotion, but I have written a Python package called log-with-context that solves this problem. You can find it on PyPI and GitHub. Here is how to use log-with-context to log messages using an arbitrary number of thread-local context values.

1. Install log-with-context and a log formatter.

You have to pair log-with-context with a different logger that displays extra fields. My favorite log formatter is JSON-log-formatter.

You can install both packages with pip:

pip3 install log-with-context JSON-log-formatter

2. Configure the log formatter.

Here is how to configure JSON-log-formatter to print JSON logs of INFO and worse to standard error.

import logging.config

logging.config.dictConfig({
    "version": 1,
    "disable_existing_loggers": True,
    "formatters": {
        "json": {"()": "json_log_formatter.JSONFormatter"},
    },
    "handlers": {
        "console": {
            "formatter": "json",
            "class": "logging.StreamHandler",
        }
    },
    "loggers": {
        "": {"handlers": ["console"], "level": "INFO"},
    },
})

3. Create a new logger using log-with-context.

Then, here is how to create your logger:

from log_with_context import add_logging_context, Logger

LOGGER = Logger(__name__)

4. Log messages using the add_logging_context context manager.

You can push and pop context keys and values using the add_logging_context context manager. Here is some example code to show how to use the context manager:

with add_logging_context(current_request="hi"):
    LOGGER.info("Level 1")

    with add_logging_context(more_info="this"):
        LOGGER.warning("Level 2")

    LOGGER.info("Back to level 1")

LOGGER.error("No context at all...")

And this is what the above log messages look like when printed as JSON:

{"current_request": "hi", "message": "Level 1", "time": "2021-08-03T21:29:45.987392"}
{"current_request": "hi", "more_info": "this", "message": "Level 2", "time": "2021-08-03T21:29:45.988786"}
{"current_request": "hi", "message": "Back to level 1", "time": "2021-08-03T21:29:45.989178"}
{"message": "No context at all...", "time": "2021-08-03T21:29:45.989600"}