getsentry / getsentry/sentry-python
Logging integration blocks the event loop for seconds while serializing frame locals on FastAPI >= 0.137
- Lenguaje dominante
- Python
- Estrellas
- 2.2k
- Forks
- 669
- Merge medio
- 1 d 1 h
- PR fusionados (30 d)
- 213
Descripción
## Steps to reproduce
No artificial `__repr__` — plain FastAPI routes are enough. The delay scales with the number of routes in the app:
```python
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:
```text
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:
```text
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 < 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`:
```python
# 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`:
```python
# 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:
```python
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.
Guía de contribución
Línea de trabajo
Start with sentry_sdk/utils.py, especially safe_repr and strip_string, then trace the LoggingIntegration callHandlers path that handles ERROR records with exc_info. Run the supplied reproduction with include_local_variables enabled against the two FastAPI versions and profile frame-local serialization. Done means the normal FastAPI error path no longer materializes the full router graph or blocks for seconds while retaining the intended local-variable capture.
Escrito por el modelo de indexación a partir del texto del issue.
Evaluación
- Stack tecnológico
- fastapi, python
- Área
- api, backend, observability, performance
- Tipo de issue
- Error
- Dificultad
- 4/5
- Tiempo estimado
- 3-5 días
- Estado de actividad
- Tranquilo
- Claridad
- Bastante claro
- Aptitud para principiantes
- 50/100