feat(metrics): per-endpoint RPC attempt metrics + timeout reasons#156
Conversation
Attribute upstream RPC latency, failure reason, and timeout counts per
endpoint instead of collapsing every provider into one method-keyed series,
so operators can tell the witness-generator primary from the failover and
see where a witness fetch's deadline budget goes.
- stateless-common: `RpcMetrics::on_rpc_complete` becomes `on_rpc_attempt`,
carrying the endpoint `provider` label and an `RpcAttemptOutcome`
(success/error/timeout); add `on_rpc_deadline_exceeded` for the
logical-call give-up. `round_robin_with_backoff` classifies each attempt,
tags it with a credential-stripped endpoint host (`endpoint_label`), and
records the deadline give-up once at every bail site. Per-attempt WARN/DEBUG
logs now include the endpoint host.
- debug-trace-server: replace `UpstreamMetrics` (method-only, success bool)
with `(method, provider, outcome)`-keyed attempt series plus a
`upstream_deadline_exceeded_total{method}` counter.
- stateless-validator: adapt `ValidatorMetrics` to the new trait and add
`stateless_validator_rpc_deadline_exceeded_total{method}`.
Tests: `endpoint_label` host/credential handling, and a capturing
`RpcMetrics` mock asserting per-endpoint attempt outcomes and a single
deadline-exceeded per logical call.
Failure attribution was already per-endpoint (metrics + WARN/DEBUG logs carry the host), but a *successful* witness fetch only logged decode time without saying which of the fallback endpoints served it. Thread the endpoint label through the per-attempt closure so `fetch_witness_with` tags its success trace with `provider`, and split `request_ms` (RPC round trip) from `decode_ms` (CPU decode) so a slow fetch across multiple witness fallbacks can be attributed to the right endpoint and stage.
The generic retry loop's per-attempt failure logs (endpoint stalled / failed) carried `method` and the endpoint host but no block identifier — the loop is generic and has no block context. Wrap the witness retry in a `warn`-level span carrying `block_number`/`block_hash` so those logs inherit it and an endpoint stall is traceable to its block. The span is `warn` level so it stays enabled at the default `warn` filter; a captured- log test asserts the stall WARN carries `block_number` at that filter.
The retry loop indexes `provider_labels[provider_idx]` where `provider_idx` is bounded by `providers.len()`, so a future edit that let the two slices desync would panic in the hot path. Both slices are built from the same endpoint list today; a `debug_assert_eq!` at the loop entry makes that parallel-by-index invariant explicit and trips it in tests/CI if it breaks.
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: c20157a705
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
| let after_scheme = url.split_once("://").map_or(url, |(_, rest)| rest); | ||
| let authority = after_scheme.split(['/', '?', '#']).next().unwrap_or(""); | ||
| let host = authority.rsplit_once('@').map_or(authority, |(_, host)| host); | ||
| if host.is_empty() { Arc::from(format!("provider_{idx}")) } else { Arc::from(host) } |
There was a problem hiding this comment.
When two configured RPC URLs share the same authority but differ by path or credentials (for example two provider keys under the same SaaS host), this returns the same provider label for both, so the new (method, provider, outcome) metrics aggregate their successes, errors, and timeouts instead of attributing them per configured endpoint. Including the stable provider index in the sanitized label would keep credentials out while preserving the per-endpoint split this change is meant to expose.
Useful? React with 👍 / 👎.
| match tokio::time::timeout( | ||
| attempt_timeout, | ||
| f(providers[provider_idx].clone(), Arc::clone(&provider_labels[provider_idx])), |
There was a problem hiding this comment.
When a caller supplies a tight deadline, attempt_timeout can be just the remaining caller budget, and for witness/block calls this f(...) future also includes local decode or verification work after the response arrives. If that budget or CPU work expires, the attempt is still recorded as outcome="timeout" for the current provider, so the new per-provider timeout metric can falsely attribute deadline pressure or local decode slowness to an upstream stall. Only classify timeouts around the actual provider round trip as provider timeouts, or use a separate outcome for deadline/decode expiry.
Useful? React with 👍 / 👎.
The witness-failure-log test used per_attempt_timeout=80ms vs a 120ms deadline (40ms margin), so on a loaded CI runner the per-attempt timeout fired after the deadline, taking the deadline-exceeded branch (no log) instead of emitting the stall WARN — a flaky pass/fail. Switch to deadline=None so every per-attempt timeout emits the stall WARN (no deadline branch can steal it), bounded by an outer tokio timeout; the assertion no longer depends on runner timing.
Two accuracy fixes from PR review:
- Deadline-pressure timeouts no longer blame the provider. When a caller's
deadline clamps the per-attempt window below `per_attempt_timeout`, a
timeout there is the caller's exhausted budget, not a provider stall.
Record it against the deadline (`on_rpc_deadline_exceeded`) only, not as a
per-provider `outcome="timeout"`, so the timeout metric reflects genuine
upstream stalls (full window elapsed with budget remaining).
- Endpoint labels are now `{idx}:{host}` so two endpoints sharing an
authority (same SaaS host, different path/credentials) stay distinct
instead of aggregating into one series; the index also encodes primary (0)
vs failover (1+). Credentials are still stripped.
3 participants
Summary
Witness fetches hit the primary (witness-generator) and fall back to Cloudflare/R2 under one shared 3s deadline, but the metrics collapsed every provider — and every failure reason — into a single
method-keyed series, and the retry loop's failure logs named neither the endpoint nor the block. There was no way to answer "did this 3s go to the witness-generator or the failover?", "how many were timeouts vs errors?", or "which block stalled on which endpoint?".This PR attributes upstream RPC latency, failure reason, timeout counts, and per-attempt logs per endpoint, for any number of fallback endpoints. The mechanism lives in the shared
round_robin_with_backoffretry loop, so both binaries benefit; the debug-trace-server (the witness path the on-call was investigating) gets the full per-endpoint Prometheus treatment.What changed
stateless-common(shared retry loop + trait)RpcMetrics::on_rpc_complete(method, success, duration)→on_rpc_attempt(method, provider, outcome, duration), whereoutcomeis a newRpcAttemptOutcome { Success, Error, Timeout }— splits a provider that returned an error from one that stalled and had to be timed out.on_rpc_deadline_exceeded(method, elapsed)(default no-op) — the operator-facing "the whole logical call blew its deadline" signal, recorded exactly once per call.round_robin_with_backoffclassifies each attempt, tags it with a bounded, credential-stripped endpoint label (endpoint_label, format{idx}:{host}, stripsuser:pass@/path/query), and threads that label into the per-attempt WARN/DEBUG logs.timeoutcounts genuine provider stalls only — a timeout that fired merely because the caller's deadline clamped the attempt window (deadline pressure, not an upstream stall) is attributed todeadline_exceeded, not blamed on the provider.request_ms(RPC round trip) fromdecode_ms(CPU decode).warn-level span carriesblock_number/block_hasharound the witness retry, so the generic loop's per-attempt failure logs inherit the block identifier (they have no block context of their own).set_validated_blocks(single attempt, outside the loop) classifies its own outcome the same way.debug-trace-serverUpstreamMetrics(asuccessbool) with(method, provider, outcome)-keyed attempt series plus a per-method deadline-exceeded counter.stateless-validatorValidatorMetricsto the new trait; addedstateless_validator_rpc_deadline_exceeded_total{method}.Metrics
debug-trace-server:
debug_trace_upstream_requests_total{method, provider, outcome}— one per provider attempt that ran its course (outcome∈success|error|timeout).debug_trace_upstream_duration_seconds{method, provider, outcome}— per-attempt latency, per endpoint.debug_trace_upstream_deadline_exceeded_total{method}— new: logical calls that exhausted their deadline budget (also absorbs deadline-pressure timeouts).stateless-validator:
stateless_validator_rpc_deadline_exceeded_total{method}— new.provideris{idx}:{host}— the host is human-readable, and the leading index keeps two endpoints that share an authority distinct while encoding primary (0) vs failover (1+). Sosum by (provider)gives the per-endpoint split for any number of fallbacks.Logs
Per-attempt failure logs (stall / error) carry
method,provider=<idx:host>,provider_idx, and — via the span —block_number. Successful witness fetches traceprovider,request_ms,decode_ms. So a stall reads directly: which block, which endpoint, which method, how long. (A stall now logs once with its reason instead of also emitting a redundant "trying next".)Operational note (dashboards)
Same class of change as #154 — dashboards/alerts need a small rebase when this deploys:
debug_trace_upstream_errors_totalis removed; error count is nowdebug_trace_upstream_requests_total{outcome=~"error|timeout"}, timeouts separable as{outcome="timeout"}(genuine stalls; deadline pressure lives indebug_trace_upstream_deadline_exceeded_total).debug_trace_upstream_requests_total/debug_trace_upstream_duration_secondsgainedprovider+outcomelabels — aggregating queries keep working; addby (...)where needed.providerlabel, so they appear on first attempt; the deadline-exceeded counter is pre-registered per method.Testing
cargo test --workspace: passes (network integration tests ignored as usual);fmt/clippy --workspace --all-targets --all-featuresclean.endpoint_labelhost extraction + credential/userinfo stripping + same-host{idx}disambiguation;RpcAttemptOutcome; a capturingRpcMetricsmock asserting per-endpoint attempt outcomes on a primary-fails/backup-succeeds failover and exactly oneon_rpc_deadline_exceededper deadline-exhausted call; and a captured-log test asserting the stall WARN carriesblock_numberat the defaultwarnfilter (deadline-independent so it can't flake on CI timing).Notes
mega-rethconsumesstateless-commonbut does not implementRpcMetrics, so the trait change is contained to this repo; it needs no change when it next bumps thestateless-commontag.provider_labelsare parallel-by-index toproviders; adebug_assert_eq!at the retry-loop entry makes that invariant explicit.