[QUESTION] Use logger.contextualize through a query, INCLUDING response from API

[AudePertron]

Hi, I'm using loguru with FastAPI. I need to identify the different requests made to my endpoints in the logs, and as there are asynchronous calls, I use:

logger.contextualize(req_id = req_id)

The problem is that the last log line (the "200 OK") will not have the proper request ID. For example, if I do :

@app.get("/about")
async def test_version(request: Request):
    req_id = "123456"
    with logger.contextualize(id_log= f"reqId={req_id}"):
        logger.info(f"example request")
        return {"version": version, "description": "a test module"}

The log will be:

[123456] example request
[default] 127.0.0.1 "GET"......200

How can I have the proper request ID on the final response ?

[Delgan]

Hi.

Where does the "200 OK" log come from? It's probably related to FastAPI, so there's not much Loguru can do to help you. You need to find a way to pass the value to the place where the logging is done.

[AudePertron]

This log actually comes from Uvicorn. but the weird part is I am using the InterceptHandler bit of code that's in loguru's documentation and all my logs are as I want them, even the endpoints with various calls to different functions and librairies keep the proper request ID along all the request, even logs coming from libraries. It's just the final response that doesn't have it and goes back to the default ID.

class InterceptHandler(logging.Handler):
    def emit(self, record):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno
        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1
        logger.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())

def setup_logging():
    # intercept everything at the root logger
    logging.root.handlers = [InterceptHandler()]
    for name in logging.root.manager.loggerDict.keys():
        logging.getLogger(name).handlers = []
        logging.getLogger(name).propagate = True
    logger.configure(handlers=[{"sink": sys.stdout}])

[Delgan]

I'm sorry but I don't know FastAPI / Uvicorn enough to be of any help here.

This StackOverflow questions seems related: Logging UUID per API request in Python FastAPI.

Maybe if you provide a minimal reproducible example I might be able to take a look at it. As it is, all I can assume is that the message is logged outside of logger.contextualize() scope and that's why you don't have the desired result.

[AudePertron]

The example you point to in StackOverflow doesn't work for me as I'm doing asynchronous work. Here is the minimal reproducible example:

import sys
import uvicorn
import logging

from loguru import logger
from fastapi import FastAPI


class InterceptHandler(logging.Handler):
    def emit(self, record):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno
        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1
        logger.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())

def setup_logging():
    # intercept everything at the root logger
    logging.root.handlers = [InterceptHandler()]
    for name in logging.root.manager.loggerDict.keys():
        logging.getLogger(name).handlers = []
        logging.getLogger(name).propagate = True
    logger.configure(handlers=[{"sink": sys.stdout}])


logging.basicConfig(handlers=[InterceptHandler()], level=0)
req_id = "default_ID"
logger.configure(extra={"id_log" : f"reqId={req_id}"})
setup_logging()
logger.remove()
log_format = "<green>{time:YYYY-MM-DD HH:mm:ss}</green> <level>{level: <8}</level> <cyan>[{extra[id_log]}]</cyan> >> <level>{message}</level>"
logger.add(sys.stderr, colorize=True, enqueue=True, backtrace=True, format=log_format, catch=True)

app = FastAPI()

@app.get("/about")
async def test_version():
    req_id = "123456"
    with logger.contextualize(id_log= f"reqId={req_id}"):
        logger.info(f"example request")
        return {"description": "a test module"}


if __name__ == "__main__":
    uvicorn.run("test:app", reload=True, access_log=True)

It returns:

2022-03-25 11:03:11 INFO     [reqId=default_ID] >> Started server process [14460]
2022-03-25 11:03:11 INFO     [reqId=default_ID] >> Waiting for application startup.
2022-03-25 11:03:11 INFO     [reqId=default_ID] >> Application startup complete.
2022-03-25 11:03:22 INFO     [reqId=123456] >> example request
2022-03-25 11:03:22 INFO     [reqId=default_ID] >> 127.0.0.1:58158 - "GET /about HTTP/1.1" 200

What I would like is the last line with reqID=123456. For the moment the workaround I found was to pass uvicorn logs in DEBUG (so as not to loose them completely) and log the "200 OK" myself in INFO, but it's not really clean and I'm not satisfied with this method.

[alexsanderp]

I have this same problem using flask and fastapi, possibly the response log is not in the same context. Any idea how I could get to this?