Skip to content

fix: report retry count on llm:response so a retried call stops looking clean - #38

Closed
Michael J. Jabbour (michaeljabbour) wants to merge 1 commit into
mainfrom
fix/retry-observability-gaps
Closed

fix: report retry count on llm:response so a retried call stops looking clean#38
Michael J. Jabbour (michaeljabbour) wants to merge 1 commit into
mainfrom
fix/retry-observability-gaps

Conversation

@michaeljabbour

Copy link
Copy Markdown
Contributor

Summary

  • llm:response now carries retries — the number of retries burned inside that one logical call — on the success path and on both error paths.
  • Fixes the failure mode where a call that swallowed three 600 s timeouts reported as a single clean success, invisible to every latency metric that keys on status.
  • Additive only. No contract change, no behavior change to the call itself.

The bug

From the forensic report on session eec9ae98, §7:

A 30-minute failure was logged as success. The resume-2 turn spent 14:19:26 → 14:49:44 on three sequential 600 s timeouts. The eventual response recorded duration_ms: 1818942 (30.3 min) with status: ok — one "successful" call swallowing three timeouts, hiding the failure from any latency metric.

The same section reports 4 of 10 provider failures never appeared in events.jsonl at all.

Root cause

Verified by reading amplifier_core.utils.retry.retry_with_backoff: on_retry is invoked only before a retry sleep. Two paths raise without ever notifying it:

  1. a non-retryable error — raised immediately, never retried;
  2. the terminal failure — once retries are exhausted, it raises without a final callback.

So the most important failure in any sequence is precisely the one the provider:retry stream never sees.

Meanwhile elapsed_ms already spans the whole retry loop, so a long duration was indistinguishable from a slow model — and llm:response, the one event every consumer already reads, said nothing about attempts at all.

What changed

amplifier_module_provider_vllm/__init__.py — track the retry count in the enclosing scope (_on_retry records attempt via nonlocal) and emit it as retries on llm:response in all three exit paths: success, and the two error paths on_retry never reaches.

A 30-minute success now describes itself:

status: ok, duration_ms: 1818942, retries: 3

retries is always present, including as 0. An absent key is indistinguishable from an old producer, so consumers never have to guess whether "missing" means none or not-reported.

Tests

tests/test_retry_observability.py — five tests, one per shape that mattered in the incident:

Test What it pins
test_a_success_that_swallowed_retries_reports_them The incident's exact shape: status: ok hiding retries
test_a_clean_success_reports_no_retries retries: 0 is present and zero, not absent
test_a_terminal_failure_reports_what_it_cost The only record that exists — on_retry never fires there
test_a_non_retryable_failure_reports_zero Raised immediately; on_retry never fires here either
test_duration_and_retries_are_reported_together Neither is actionable alone (see below)

That last one is the point of the whole change: 30 minutes with retries: 0 is a slow model; 30 minutes with retries: 3 is three dead connections. The incident could not tell those apart.

Verification

$ uv run ruff check .
All checks passed!

$ uv run ruff format --check amplifier_module_provider_vllm/__init__.py tests/test_retry_observability.py
2 files already formatted

$ uv run pytest -q
298 passed in 1.58s

Baseline on main is 293; the five new tests bring it to 298.

New tests in isolation:

$ uv run pytest tests/test_retry_observability.py -v
tests/test_retry_observability.py::test_a_success_that_swallowed_retries_reports_them PASSED [ 20%]
tests/test_retry_observability.py::test_a_clean_success_reports_no_retries PASSED         [ 40%]
tests/test_retry_observability.py::test_a_terminal_failure_reports_what_it_cost PASSED    [ 60%]
tests/test_retry_observability.py::test_a_non_retryable_failure_reports_zero PASSED       [ 80%]
tests/test_retry_observability.py::test_duration_and_retries_are_reported_together PASSED [100%]

5 passed in 0.45s

What this does not fix

Stating this plainly so the PR isn't read as more than it is:

  • Retry policy is untouched. §7 also reports backoff delays of 0.52–5.52 s against 600 s timeouts. Whether those delays are sensibly sized against that timeout is a real question, and this PR does not answer it — it only makes the cost of the current policy visible.
  • anchors:builder delegate failures (§7d) are out of scope. They live in a different repo.

This change makes the failures legible. It does not make them stop.

Note on pre-existing format drift

Five test files in this repo have ruff format drift that predates this branch. They are deliberately left alone as out of scope.

Confirmed by checking the pristine HEAD blobs directly (no worktree mutation): 6 files drift on pristine main, 5 with this work applied. The difference is amplifier_module_provider_vllm/__init__.py itself — this PR contains one incidental formatting hunk collapsing a continuation_input.append(...) call in a function it touches, which is why the count drops by one. Both files this PR changes pass ruff format --check.

Related

Sibling PRs from the same incident:

🤖 Generated with Amplifier

…ng clean

A 30-minute failure was logged as a success. In session `eec9ae98` the
resume-2 turn spent 14:19:26 -> 14:49:44 on three sequential 600 s timeouts
and emitted one `llm:response` with `duration_ms: 1818942` (30.3 min) and
`status: ok` -- a single "successful" call swallowing three timeouts, hiding
the failure from every latency metric that keys on status. The same forensic
section reports 4 of 10 provider failures never reached `events.jsonl` at all.

Root cause, from `amplifier_core.utils.retry.retry_with_backoff`: `on_retry`
is invoked only before a retry *sleep*. Two paths raise without ever calling
it -- a non-retryable error, and the terminal failure once retries are
exhausted. So the most important failure in any sequence is precisely the one
the `provider:retry` stream never sees. Meanwhile `elapsed_ms` already spans
the whole retry loop, so a long duration was indistinguishable from a slow
model, and `llm:response` -- the one event every consumer already reads --
said nothing about attempts at all.

Track the retry count inside the call and surface it as `retries` on
`llm:response`: on the success path and on both error paths, so the two paths
`on_retry` never reaches are covered. A 30-minute success now describes
itself: `status: ok, duration_ms: 1818942, retries: 3`.

Additive, no contract change. `retries` is always present -- an absent key is
indistinguishable from an old producer, so consumers never have to guess
whether zero means "none" or "not reported".

Five tests cover the shapes that mattered in the incident: a success that
swallowed retries reports them; a clean success reports `retries: 0`; a
terminal failure reports what it cost (the only record, since `on_retry`
never fires there); a non-retryable failure reports zero; and duration and
retries are reported together, because neither is actionable alone.

Also collapses one pre-existing `ruff format` drift in the touched function,
which is why the repo's format drift drops from 6 files to 5.

Verified: `ruff check` clean, 298 passed (baseline 293).

🤖 Generated with [Amplifier](https://github.com/microsoft/amplifier)

Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com>
@michaeljabbour

Copy link
Copy Markdown
Contributor Author

Withdrawing this. It was pushed as a branch directly into this repo; it should
have gone to a fork, and it is now preserved at
michaeljabbour/amplifier-module-provider-vllm on branch
fix/retry-observability-gaps (38638b3f8bf4) if any of it is useful. Closing
rather than leaving it open so it does not sit in the queue ahead of work that
was here first.

No conflict with anyone else's work here; withdrawing for consistency. The
finding: retry_with_backoff only invokes on_retry before a retry sleep,
so a non-retryable error and the final exhausted attempt emit nothing — the
most important failure in a sequence is the one the retry stream never sees.

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.

1 participant