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

从 sentry_sdk/utils.py 开始，重点查看 safe_repr 和 strip_string，然后跟踪处理带有 exc_info 的 ERROR 记录的 LoggingIntegration callHandlers 路径。在两个 FastAPI 版本上启用 include_local_variables 运行提供的复现，并对 frame 局部变量的序列化进行性能分析。完成标准是：正常的 FastAPI 错误路径不再实例化完整的路由器图，也不再阻塞数秒，同时保留预期的局部变量捕获功能。

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.