Have you ever been in a situation where your server receives multiple requests at once and the log is all messed up? I have.

(lazy post, just want to get the idea out there)

Problem description

Say we have a toy program.

import asyncio
import logging
from fastapi import FastAPI

logging.basicConfig()
logger = logging.getLogger()

app = FastAPI()


@app.get("/{n}")
async def hello(n: int):
    logger.info(f"Start {n}")
    await asyncio.sleep(1)
    logger.info(f"End {n}")

If we send two requests in parallel with curl localhost:8000/1 & curl localhost:8000/2, ee might see this:

INFO:     Start 2
INFO:     Start 1
INFO:     End 2
INFO:     127.0.0.1:61256 - "GET /2 HTTP/1.1" 200 OK
INFO:     End 1
INFO:     127.0.0.1:61257 - "GET /1 HTTP/1.1" 200 OK

Not great. You can imagine how it becomes extremely difficult to track where and why log rows were printed as the code gets more complex.

Solution

import asyncio
import logging

from contextvars import ContextVar
from datetime import datetime
from fastapi import Depends, FastAPI, Request


def outside_request_log(record: logging.LogRecord):
    msg = record.msg % record.args
    line = f"{datetime.now().isoformat()} - {record.levelname} - {msg}"
    print(line)


class RequestInfo:
    start_time: datetime
    records: list[logging.LogRecord]
    request: Request

    def __init__(self, request: Request) -> None:
        self.start_time = datetime.now()
        self.records = []
        self.request = request

    def send(self):
        start_t = self.start_time.timestamp()
        output = [""]
        output.append(
            f"{self.start_time.isoformat()} - {self.request.method} {self.request.url}"
        )
        for record in self.records:
            age = record.created - start_t
            msg = record.msg % record.args
            line = f"  {age:.2f} - {record.levelname} - {msg}"
            output.append(line)

        print("\n".join(output))


REQUEST = ContextVar[RequestInfo]("RequestInfo")


class AsyncHandler(logging.Handler):
    def emit(self, record: logging.LogRecord) -> None:
        try:
            info = REQUEST.get()
            info.records.append(record)
        except LookupError:
            # Not in a request
            outside_request_log(record)


def install():
    logging.basicConfig(level=logging.DEBUG, handlers=[AsyncHandler()])


async def request_dependency(request: Request):
    info = RequestInfo(request)
    REQUEST.set(info)
    try:
        yield
    finally:
        info.send()


install()
logger = logging.getLogger()

app = FastAPI(dependencies=[Depends(request_dependency)])


@app.get("/{n}")
async def hello(n: int):
    logger.info(f"Start {n}")
    await asyncio.sleep(1)
    logger.info(f"End {n}")

With this, the output is quite different!

2025-10-22T18:09:11.945030 - GET http://localhost:8000/1
  0.00 - INFO - Start 1
  1.00 - INFO - End 1

2025-10-22T18:09:11.945296 - GET http://localhost:8000/2
  0.00 - INFO - Start 2
  1.00 - INFO - End 2