getsentry / getsentry/sentry-python

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

Abierto
#6,649 7 comentarios 2 reacciones 0 asignados Ver en GitHub
Bug Logs Python Waiting for: Product Owner
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

Abrir la 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

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.