Idiomatic way to prepend an identifier to python's logger for the duration of some request?

Question

I have a server used by many clients. In order to make finding log entries easier, I wanted to allow the client to supply a UUID for each request, and then prepend each log message with that UUID for the duration of the request. The benefit to this is that the client can supply the ID to me if they encounter some bug, and I would be able to quickly find it in the logs. I assume this is pretty standard; is there any idiomatic was of accomplishing this task in Python?

I could do this naively by manually prepending the uuid to each log message:

import uuid
import logging
logger = logging.getLogger(__name__)

def request(*args, **kwargs):
    _id = args.get("_id", str(uuid.uuid4()))
    logger.info("{} - {}".format(_id, "Starting request"))

I could also create a new logger for each request, and change the formatter to take care of prepending for me:

import uuid
import logging

def build_logger(_id):
    logger = logging.getLogger(_id)
    # ...
    formatter = logging.Formatter('%(name)s - %(message)s')
    # ...
    return logger

import uuid
def request(*args, **kwargs):
   _id = args.get("_id", str(uuid.uuid4()))
    logger = build_logger(_id)

Then I thought that I could perhaps create a proxy class, that would intercept calls to info, debug, exception, and etc, and prepend the uuid. Something like:

import uuid
import logging
logger = logging.getLogger(__name__)

class Logger(object):
    """Naive Proxy class for logger"""
    def __init__(self, _id):
        self._id = _id
    def debug(self, msg):
        logger.debug("{} - {}".format(self._id, msg)
    def info(self, msg):
        logger.info("{} - {}".format(self._id, msg)
    # and etc. for each level and `exception`

def request(*args, **kwargs):
    _id = args.get("_id", str(uuid.uuid4()))
    logger = Logger(_id)

And why not collapse these using __getattr__ and a decorator?

import uuid
import logging
logger = logging.getLogger(__name__)

def loggerator(_id):
    """
    Decorator to intercept `info`, `debug`, etc. and prepend the `_id`
    Used in the Logger Proxy class
    """
    def _loggerator(func):
        def __loggerator(msg):
            return func("{} - {}".format(_id, msg))
        return __loggerator
    return _loggerator

class Logger(object):
    """Proxy class for logger"""
    def __init__(self, _id):
        self._id = _id
    def __getattr__(self, item):
        if item == '_id':
            return object.__getattribute__(self, item)
        if item in ('debug', 'info', 'warn', 'warning', 'error', 'critical', 'fatal', 'exception'):
            return loggerator(self._id)(getattr(logger, item))
        return getattr(logger, item)

def request(*args, **kwargs):
    _id = args.get("_id", str(uuid.uuid4()))
    logger = Logger(_id)

Answer 1

How to do this is documented in the Logging Cookbook, which is part of the Python documentation.

Answer 2

Using the link provided by Vinay (specifically here), this is how I did it in Flask:

In @app.before_request, get the user provided UUID from the X-Request-Id header. If it is not provided, create a uuid4. Make sure to validate that it is a real uuid4 since the user may provide it:

from flask import g, request
import uuid


@app.before_request
def before_request():
    g.request_id = request.headers.get('X-Request-Id', str(uuid.uuid4())

    if not is_valid_uuid(g.request_id):
        raise BadInput('X-Request-Id must be a valid UUID4 string')


def is_valid_uuid(value):
    try:
        uuid.UUID(value, version=4)
    except ValueError:
        return False

    return True

In wsgi.py, subclass logging.Filter to add contextual information (in this case, g.request_id.

Note that in Flask you'll want to check has_app_context so your logger won't raise errors during unit testing.

import logging


class RequestFilter(logging.Filter):
    """
    This will add the g.request_id to the logger
    """
    def filter(self, record):
        if has_app_context() and hasattr(g, 'request_id'):
            record.request_id = g.request_id
        else:
            record.request_id = '-'
        return record

handler = logging.StreamHandler()
handler.setLevel(logging.DEBUG)
handler.setFormatter(logging.Formatter('[%(asctime)s.%(msecs)03d] [%(request_id)s] [%(levelname)s] [%(module)s.%(funcName)s]: %(message)s'))
handler.addFilter(RequestFilter())