fix(telemetry): scope the winning attempt's latency_ms to that attempt

[jarvis9443]

Problem

UsageEvent.latency_ms is documented as scoped to ONE upstream attempt — that is what makes a request's per-attempt events summable:

// `status_code`, `latency_ms`, and `ttft_ms` are scoped to THIS attempt

Failed attempts honored it (ms_since(attempt_started)), but most winning attempts reported started.elapsed() — the whole request, measured from handler entry. A winner's latency therefore swallowed every failed attempt that preceded it, plus request parsing, guardrail scans and the retry backoff.

Observed on a real failover request: an initial attempt that burned 430ms, then a streamed winner on the same target. The two events read 430ms and 13578ms, so summing them gave 14008ms — the winner's figure already contained the loser's 430ms and ~4.6s of pre-dispatch work.

What changed

Only /v1/chat/completions' non-streaming path was already correct (it used the winner's AttemptRecord.latency_ms). The rest of the handler family now matches:

site	before	after
chat.rs streaming end-of-stream	started.elapsed()	winner's attempt_started.elapsed() (carried on StreamWin)
chat.rs billed-then-blocked terminal	elapsed	winner's AttemptRecord.latency_ms
messages.rs non-streaming winner	elapsed	winner's AttemptRecord.latency_ms
messages.rs native-Anthropic + cross-provider streaming	started.elapsed()	attempt_started.elapsed()
responses.rs non-streaming winner	elapsed	winner's AttemptRecord.latency_ms
responses.rs verbatim + cross-provider streaming	started.elapsed()	attempt_started.elapsed()

attempt_started is threaded through dispatch_to_target / responses_to_target / responses_cross_provider_to_target.

Untouched by design:

• record_request_e2e_latency (SLO histograms) and the access log's latency_ms stay request-scoped — that is what they are for.
• Endpoints emitting a single event with no per-attempt failure rows (embeddings, rerank, completions, audio, images, passthrough) have no second event to double-count against.
• Ensemble panel/judge sub-call events (attempt_kind="panel") are sub-calls rather than attempts of one target; left as-is.

The UsageEvent contract now also states the measurement boundaries: what an attempt's latency does and does not include, that a streamed attempt is measured to end-of-stream (ttft_ms carries the first-token figure), and that summing attempts yields upstream time rather than the user-perceived total.

Behavior change worth flagging

cp-api's MetricsByEnv computes request latency percentiles as SUM(latency_ms) GROUP BY request_id. Before this change that sum double-counted failed attempts, so p50/p99 for requests that retried or failed over were inflated; they will drop to the real upstream time. Requests that succeeded first try are unaffected (single event, and the winner's own latency is what it always was minus pre-dispatch work).

The sum is not the user-perceived total either way — that figure lives in the access log and has no UsageEvent field today. cp-api's comment on MetricsByEnv calls the sum "user-perceived total"; that wording is now the inaccurate part, and whether to add a request-scoped field or restate the metric is a separate call.

Tests

Two E2E regressions in per-attempt-telemetry-e2e.test.ts, one non-streaming (/v1/responses) and one streaming, each failing over from a deliberately slow 502 primary (700ms) to a fast secondary. A correctly scoped winner is far faster than the loser it followed; a request-scoped one is necessarily slower because it contains it.

Both assertions fail before this change (734ms and 705ms observed against a 350ms bound) and pass after. The OTLP receiver recovers each event's latency_ms from its span duration, since the sink derives span start as occurred_at - latency_ms.

Also run: cargo test --workspace, cargo clippy --workspace --all-targets, cargo fmt --check, and the 17 usage/streaming/latency/retry E2E files (26 tests).

🤖 Generated with Claude Code