Skip to content

fix(api): make the 504 name the layer that ate the request budget (ax-0917-h-01/h-02) - #1707

Merged
arkash20 merged 1 commit into
mainfrom
fix/ax-h01-h02-timeout-attribution
Sep 23, 2026
Merged

arkash20 merged 1 commit into
mainfrom
fix/ax-h01-h02-timeout-attribution

Conversation

@arkash20

Copy link
Copy Markdown
Contributor

#1633 gave the request-budget 504 the canonical envelope
(REQUEST_BUDGET_EXCEEDED, budget_seconds/elapsed_seconds/path,
Retry-After, a structured log line), and h-01/h-02 then closed as
partial on the plan "the next occurrence will say which layer ate the
budget"
.

Driven against the real app stack, that plan does not hold. A stalled
embedding provider and a stalled storage read produce byte-identical
evidence — same code, same three details, same log record. Nothing in
#1633 records what was running.

This adds the missing half.

request_phase — a phase stack per request

RequestTimeoutMiddleware arms a recorder before SlowAPI's
BaseHTTPMiddleware splits the task, and reports it on timeout. Each
bounded hop announces itself with phase(...); on the cancellation
unwind the recorder holds the stack that was in flight.

The 504 now carries phase (the single-field answer), phases_cancelled
(innermost first — the layer), and phases_completed (what had already
finished, which is how "the pipeline was fine until here" gets said).
error.message names the phase too, for a caller that logs only that.
The same fields go on the log record, flat and top-level, so "which layer
is eating budgets, how often" is a groupable log query rather than a
grep.

Instrumented: every pipeline step (search and write, one edit in the
runner), the shared query-embedding hop, both per-tenant slot acquires,
and every storage roundtrip via _execute's existing bounded label.
phase() is a no-op when nothing is armed, so the same calls are safe
from background tasks and MCP.

The principle is already written down one layer lower, beside
EMBEDDING_GATE_TIMEOUT_SECONDS: "a cancellation carries no attribution
— it says the deadline passed, not which layer ate it."
That module
solved it by failing under its caller's budget. The outermost deadline
has no such move available; it has to be told.

Two pieces of evidence that pointed the wrong way

The access log filed every budget timeout as a 500.
RequestObservationMiddleware sits inside the budget, so a cancelled
request unwinds through it with no status line ever sent and fell to its
500 default. That metric backs the per-endpoint dashboard — the first
thing an incident opens — and on 2026-09-17 it said crash while the
callers were holding 504s. Its docstring's "504s/429s aren't observed"
was true of the intent and false of the output.

The search route logged a cancelled search as a completed one.
except Exception does not catch CancelledError, so success stayed
True: search request completed … row_count=0, error=false, total_ms≈ the budget. In this route's own telemetry a timed-out search was
indistinguishable from one that legitimately matched nothing — every
timeout landed in the empty-result rate and none in the error rate. Now
error=true with an explicit cancelled field, and a genuinely empty
search is pinned as still-not-an-error.

Tests

tests/test_ax_h01_h02_timeout_attribution.py drives the production
stack — real /api/v1/search, real pipeline, real middleware order, only
the budget lowered — and stalls one hop at a time as deep as the hop
goes: the embedding provider call, the storage bulkhead queue,
PostgresService.memory_scored_search. It then compares what the two
emit, with every duration stripped, because on a real incident every 504
lands at the same ~45s and a duration that discriminates in a test would
not discriminate there.

test_the_504_names_the_layer_that_ate_the_budget is the one that
failed. 5 of the 11 fail without this change.

Still open

The latency itself, on both rows — that needs prod-side data. What
changes is that the next occurrence answers the question instead of
costing another cycle. The opt-out routes (/memories/bulk,
/admin/org/purge-data, /interview/submit) and the MCP transport
bypass this middleware and so get no attribution; their own deadlines
could arm a recorder the same way.

🤖 Generated with Claude Code

Co-Authored-By: Claude Opus 5 (1M context) noreply@anthropic.com

Signed-off-by: Arkady Mankovsky arkash20@gmail.com

@arkash20
arkash20 requested a review from a team as a code owner September 23, 2026 12:10
@github-actions

Copy link
Copy Markdown
Contributor

Claude Code Review — skipped: PR author 'arkash20' is not a public member of the 'caura-ai' org

@arkash20

Copy link
Copy Markdown
Contributor Author

@Eldad-Caura please approve

…-0917-h-01/h-02)

#1633 gave the request-budget 504 the canonical envelope
(`REQUEST_BUDGET_EXCEEDED`, `budget_seconds`/`elapsed_seconds`/`path`,
`Retry-After`, a structured log line), and h-01/h-02 then closed as
`partial` on the plan *"the next occurrence will say which layer ate the
budget"*.

Driven against the real app stack, that plan does not hold. A stalled
embedding provider and a stalled storage read produce **byte-identical**
evidence — same code, same three details, same log record. Nothing in
`#1633` records what was running.

This adds the missing half.

### `request_phase` — a phase stack per request

`RequestTimeoutMiddleware` arms a recorder before SlowAPI's
`BaseHTTPMiddleware` splits the task, and reports it on timeout. Each
bounded hop announces itself with `phase(...)`; on the cancellation
unwind the recorder holds the stack that was in flight.

The 504 now carries `phase` (the single-field answer), `phases_cancelled`
(innermost first — the layer), and `phases_completed` (what had already
finished, which is how "the pipeline was fine until here" gets said).
`error.message` names the phase too, for a caller that logs only that.
The same fields go on the log record, flat and top-level, so "which layer
is eating budgets, how often" is a groupable log query rather than a
grep.

Instrumented: every pipeline step (search and write, one edit in the
runner), the shared query-embedding hop, both per-tenant slot acquires,
and every storage roundtrip via `_execute`'s existing bounded `label`.
`phase()` is a no-op when nothing is armed, so the same calls are safe
from background tasks and MCP.

The principle is already written down one layer lower, beside
`EMBEDDING_GATE_TIMEOUT_SECONDS`: *"a cancellation carries no attribution
— it says the deadline passed, not which layer ate it."* That module
solved it by failing under its caller's budget. The outermost deadline
has no such move available; it has to be told.

### Two pieces of evidence that pointed the wrong way

**The access log filed every budget timeout as a 500.**
`RequestObservationMiddleware` sits inside the budget, so a cancelled
request unwinds through it with no status line ever sent and fell to its
`500` default. That metric backs the per-endpoint dashboard — the first
thing an incident opens — and on 2026-09-17 it said *crash* while the
callers were holding 504s. Its docstring's "504s/429s aren't observed"
was true of the intent and false of the output.

**The search route logged a cancelled search as a completed one.**
`except Exception` does not catch `CancelledError`, so `success` stayed
`True`: `search request completed … row_count=0, error=false, total_ms≈
the budget`. In this route's own telemetry a timed-out search was
indistinguishable from one that legitimately matched nothing — every
timeout landed in the empty-result rate and none in the error rate. Now
`error=true` with an explicit `cancelled` field, and a genuinely empty
search is pinned as still-not-an-error.

### Tests

`tests/test_ax_h01_h02_timeout_attribution.py` drives the production
stack — real `/api/v1/search`, real pipeline, real middleware order, only
the budget lowered — and stalls one hop at a time as deep as the hop
goes: the embedding provider call, the storage bulkhead queue,
`PostgresService.memory_scored_search`. It then **compares** what the two
emit, with every duration stripped, because on a real incident every 504
lands at the same ~45s and a duration that discriminates in a test would
not discriminate there.

`test_the_504_names_the_layer_that_ate_the_budget` is the one that
failed. 5 of the 11 fail without this change.

### Still open

The latency itself, on both rows — that needs prod-side data. What
changes is that the next occurrence answers the question instead of
costing another cycle. The opt-out routes (`/memories/bulk`,
`/admin/org/purge-data`, `/interview/submit`) and the MCP transport
bypass this middleware and so get no attribution; their own deadlines
could arm a recorder the same way.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Signed-off-by: Arkady Mankovsky <arkash20@gmail.com>
@arkash20
arkash20 force-pushed the fix/ax-h01-h02-timeout-attribution branch from 3e0dad6 to 7b5d2d8 Compare September 23, 2026 17:12
@github-actions

Copy link
Copy Markdown
Contributor

Claude Code Review — skipped: PR author 'arkash20' is not a public member of the 'caura-ai' org

@arkash20
arkash20 merged commit 68d49fa into main Sep 23, 2026
14 checks passed
@arkash20
arkash20 deleted the fix/ax-h01-h02-timeout-attribution branch September 23, 2026 20:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants