Logging integration blocks the event loop for seconds while serializing frame locals on FastAPI >= 0.137

Bắt đầu với sentry_sdk/utils.py, đặc biệt là safe_repr và strip_string, sau đó lần theo đường dẫn callHandlers của LoggingIntegration xử lý các bản ghi ERROR có exc_info. Chạy bản tái hiện được cung cấp với include_local_variables được bật trên hai phiên bản FastAPI và lập hồ sơ việc tuần tự hóa các biến cục bộ của frame. Được xem là hoàn tất khi đường dẫn lỗi FastAPI thông thường không còn materialize toàn bộ đồ thị router hoặc bị chặn trong nhiều giây, đồng thời vẫn giữ việc thu thập các biến cục bộ như dự kiến.

Steps to reproduce

No artificial __repr__ — plain FastAPI routes are enough. The delay scales with the number of routes in the app:

import os
import time
from typing import Never
import logging

from fastapi import Query, Depends, FastAPI, Request, APIRouter
from pydantic import BaseModel
import sentry_sdk
from fastapi.responses import JSONResponse
from fastapi.testclient import TestClient

sentry_sdk.init(
    dsn="https://examplekey@o0.ingest.sentry.io/0",  # fake DSN, nothing is sent
    include_local_variables=os.getenv("LOCALS", "1") == "1",  # default True
)


class Model(BaseModel):  # a typical response model
    a: int
    b: str
    c: float
    d: bool
    e: list[int]
    f: dict[str, int]


async def dep(q: str = Query("x")):
    return q


async def boom_dep() -> Never:
    raise KeyError("boom")


leaf = APIRouter()
for k in range(800):  # a non-trivial app: real services have hundreds/thousands of routes

    @leaf.get(f"/r{k}", response_model=Model)
    async def ep(d=Depends(dep)):
        return {}


@leaf.get("/boom", response_model=Model)
async def boom(_: object = Depends(boom_dep)) -> None: ...


router = leaf
for i in range(6):  # nested include_router()
    parent = APIRouter(prefix=f"/l{i}")
    parent.include_router(router)
    router = parent

app = FastAPI()
app.include_router(router)


@app.exception_handler(Exception)
async def on_error(request: Request, exc: Exception):
    t = time.perf_counter()
    logging.getLogger("x").error("err", exc_info=exc)  # ERROR + exc_info -> Sentry capture
    print(f"logger.error took {time.perf_counter() - t:.3f}s")
    return JSONResponse(status_code=500, content={})


path = "".join(f"/l{i}" for i in range(5, -1, -1)) + "/boom"
TestClient(app, raise_server_exceptions=False).get(path)

Measured locally with the repro above:

FastAPI 0.137.2:

LOCALS=1  python repro.py   # logger.error took 0.530s
LOCALS=0  python repro.py   # logger.error took 0.073s


FastAPI 0.136.3:

LOCALS=1  python repro.py   # logger.error took 0.067s
LOCALS=0  python repro.py   # logger.error took 0.084s

So the regression is specifically that include_local_variables=True used to be cheap on FastAPI 0.136.3, but becomes much slower on FastAPI >= 0.137.

Expected: capturing a single exception from a normal FastAPI route should not require materializing a representation of the whole router graph, and should not block the event loop for hundreds of milliseconds or seconds.

Actual: the logging call blocks while Sentry serializes the locals of every traceback frame. Each nested routing frame holds an _IncludedRouter (FastAPI >= 0.137) whose repr() walks the whole router graph, so the cost grows with app size — ~0.53s at 800 routes here, and seconds in a real app with thousands of routes and richer models. On FastAPI 0.136.3 this object is not in the frame locals, and the same capture is ~0.07s even with include_local_variables=True.

This was observed in production: a service was upgraded from FastAPI 0.136.3 to 0.137.2, and any unhandled exception started taking ~20s to log. Running under gunicorn's UvicornWorker, this blocks the event loop long enough to trip WORKER TIMEOUT → SIGABRT → worker restart, so a normal 500 turns into a worker kill. Reverting to FastAPI 0.136.3 restors ~0.1s.

Environment

• sentry-sdk 2.63.0
• fastapi 0.137.2 (fast on 0.136.3)
• starlette 1.3.1, uvicorn 0.49.0, gunicorn 26.0.0 (-k uvicorn.workers.UvicornWorker)
• Python 3.14

Measurements (production)

Instrumenting the exception path showed the whole delay is inside one logging call, and only when it goes through Sentry's callHandlers patch.

Walking the traceback frame-by-frame and timing exactly what Sentry does for each frame (serialize(dict(frame.f_locals), is_vars=True)) shows the cost is entirely in FastAPI's own router objects, not in any application object:

frame routing.py:handle           self / included_router  <_IncludedRouter>  ~117 MiB  ~0.96s
frame routing.py:_handle_selected  self / route            <_IncludedRouter>  ~117 MiB  ~0.95s
... repeated for every level of the nested include_router() tree (~8 frames) ...
frame <our endpoint / domain frames>  <plain app objects>                    < 1 KiB   0.000s

Each _IncludedRouter local causes a huge transient representation to be materialized before truncation, and one appears as self / route / included_router in every nested routing frame, so the total can reach ~15-20s. The application's own frame locals are negligible (0.000s) — this is not caused by a user object with a heavy __repr__; serializing FastAPI's standard per-request router graph is enough on its own.

Not the same as getsentry/sentry-python#6568 / #6569 (sync-handler _sentry_call accumulation → RecursionError after ~987 requests, fixed in 2.63.0): this affects async endpoints too, triggers on the first error, and the cost is time spent serializing locals.

Possible root cause

LoggingIntegration patches logging.Logger.callHandlers; for an ERROR record with exc_info it builds an event via event_from_exception(..., include_local_variables=True), serializing each frame's locals. A _IncludedRouter is not a Mapping/Sequence/Set, so the serializer does not appear to apply its depth/breadth limits to it — it goes to safe_repr:

# sentry_sdk/utils.py
def safe_repr(value):
    return repr(value)          # full repr is materialized here
# ...then strip_string() truncates the already-built string

FastAPI 0.137 (fastapi/fastapi#15745) stopped flattening routes on include_router(). Instead, each routing frame now holds an _IncludedRouter, which is a @dataclass:

# fastapi/routing.py
@dataclass
class _IncludedRouter(BaseRoute):
    original_router: "APIRouter"
    include_context: _RouterIncludeContext
    _effective_candidates: list["_EffectiveRouteContext | _IncludedRouter"] = field(default_factory=list)
    ...

The auto-generated dataclass __repr__ recurses through every field — original_router (and its .routes) plus the lazily-built _effective_candidates tree — i.e. effectively the whole router graph of the app. safe_repr materializes that entire string before strip_string truncates it. The same _IncludedRouter then appears as self / route / included_router in each nested routing frame, so this whole-app repr() is paid once per frame. On 0.136 routes were flattened and no such object was in the frame locals, so the capture stayed cheap.

Workarounds

sentry_sdk.init(..., include_local_variables=False) removes the delay entirely, but drops locals from every frame.

A more targeted workaround is custom_repr, which keeps locals everywhere else and only short-circuits the router objects:

def custom_repr(value):
    cls = type(value)
    module = getattr(cls, "__module__", None)

    if module in {"fastapi.routing", "starlette.routing"}:
        return f"<{module}.{cls.__name__}>"

    return None  # fall back to the default repr for everything else


sentry_sdk.init(..., custom_repr=custom_repr)

Disclosure: This issue was researched and written with the assistance of an AI (Claude) and reviewed by a human before submission. The reproduction and timings have been manually confirmed; I did not go deep into Sentry's serializer internals to verify the exact root cause or the best fix.