Add request-id to logs without using LoggerAdapter

[dev-99]

Thank you for this middleware!

I want to use it for adding request IDs in the logs of third-party libraries that I do not have control over. Since most libraries might use a logger instead of LoggerAdapter, I am wondering if there is a way to log request IDs without the use LoggerAdapter(like in the example given in this repo).

[tomwojcik]

I'm glad you like it!

For sure you can do it but I don't think there's anything I need to add in order to make it work. But lets crack it together. Could you please give me an example? What 3rd party lib?

[yinkh]

log_request_id.py

import logging
from starlette_context import context


def get_request_id():
    return context.data['X-Request-ID']



class RequestIDLogFilter(logging.Filter):
    """
    Log filter to inject the current request id of the request under `log_record.request_id`
    """

    def filter(self, log_record):
        log_record.request_id = get_request_id()
        return log_record

class RequestLogHandler(LogHandler):
    log_format = REQUEST_ID_LOG_FORMAT

    def __setFileHandler__(self, level=None):
        super(RequestLogHandler, self).__setFileHandler__(level=level)
        self.addFilter(RequestIDLogFilter())

    def __setStreamHandler__(self, level=None):
        super(RequestLogHandler, self).__setStreamHandler__(level=level)
        self.addFilter(RequestIDLogFilter())

REQUEST_ID_LOG_FORMAT = '%(asctime)s [pid:%(process)d] %(filename)s(line:%(lineno)d) %(levelname)s [%(request_id)s] %(message)s'
log = RequestLogHandler('client')

logging inside api :

log.info('demo') get
2020-09-30 13:57:43,563 [pid:12340] views.py(line:362) INFO [c493912529a14849ba6475a56af6407e] demo
what do you think?

[tomwojcik]

Hey guys.

I took my time because I struggled to set it up myself. Uvicorn + Gunicorn + Starlette logging setup is complicated beyond any expectations. And it's very, very buggy, depending on the version of each of these.

There are quite a few tickets related to logging. Most often uvicorn does something weird and you just need to make it work together.

I see that you have your own, custom logger. If we were to add filters to this project, I'd rather use a generic approach.

class RequestIDLogFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        if context.exists() and 'request_id' in context.data:
            record.request_id = context['request_id']
        else:
            record.request_id = None
        return True

@app.on_event("startup")
async def startup_event(): 
    logger = None  # first problem, what logger do you want to use? custom or default uvicorn? root?
    handler = logging.StreamHandler()
    handler.setFormatter(logging.Formatter('%(asctime)s %(request_id)s %(app_name)s : %(message)s'))
    logger.addFilter(AppFilter())
    logger.addHandler(handler)

or from config

LOGGING_CONFIG = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "custom_formatter": {
            "fmt": '%(asctime)s %(request_id)s %(app_name)s : %(message)s'
        },
        "default": {
            "()": "uvicorn.logging.DefaultFormatter",
            "fmt": "%(levelprefix)s %(message)s",
            "use_colors": None,
        },
        "access": {
            "()": "uvicorn.logging.AccessFormatter",
            "fmt": '%(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s',  # noqa: E501
        },
    },
    "filters": {
        "custom_filter": {
            "()": "app.CustomFilter",
        }
    },
    "handlers": {
        "custom_handler": {
          "formatter": "custom_formatter",
          "class": "logging.StreamHandler",
            "filters": ["custom_filter"],
          "stream": "ext://sys.stdout",
            # "stream": "logging.StreamHandler"
        },
        "default": {
            "formatter": "default",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stderr",
        },
        "access": {
            "formatter": "access",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
        },
    },
    "loggers": {
        "custom_logger": {"handlers": ["custom_handler"], "level": "DEBUG", "propagate": True},
        "uvicorn": {"handlers": ["default"], "level": "INFO"},
        "uvicorn.error": {"level": "INFO"},
        "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False},
    },
}

But none of these approaches work for me.

Around the time when you asked this question, those tickets were closed

encode/uvicorn#512
encode/uvicorn#767
encode/uvicorn#511

What I wish was closed is this

encode/uvicorn#491

If you have a working example, I will be happy to accept a contribution.

[tomwojcik]

I added a working example with:

• async logger
• setup from dict
• without adapter

https://starlette-context.readthedocs.io/en/latest/example.html