cluster upstream_rq_timeout increments on requests that also complete successfully (rq_success == rq_total, rq_timeout independently non-zero)

[aleemshah-insignis]

Summary

For one specific upstream cluster, envoy_cluster_upstream_rq_timeout (and the equivalent /clusters?format=json admin stat rq_timeout) increments on requests that also complete successfully. On the same host, in the same admin snapshot, rq_success equals rq_total exactly, while rq_timeout is simultaneously non-zero — i.e. Envoy is counting some fraction of requests as both fully successful and timed out.

This is not a rare edge case: on the affected cluster the ratio is currently 68-72% (rq_timeout/rq_total) and has persisted across proxy restarts, a route timeout config change, and an Envoy patch version bump, with the underlying application-level failure rate provably at zero throughout.

Environment

• Envoy v1.35.10 (also reproduced on v1.35.9), via Contour 1.33.3 (projectcontour/contour chart)
• Downstream: Gateway API HTTPRoute, no retry/hedge policy configured
• Upstream: a single Kubernetes Service, 2 endpoints, plain HTTP/1.1 (no TLS), StreamableHTTP/JSON-over-HTTP traffic (not gRPC)
• Traffic pattern: bursty/low-volume (roughly 1 request every few seconds), long-lived-ish client sessions, some requests carry Connection: keep-alive

Evidence

GET /clusters?format=json on the Contour-managed Envoy, same cluster, two hosts, one snapshot:

host .229:  cx_connect_fail: (absent/0)   cx_total: 226   rq_success: 290   rq_timeout: 199   rq_total: 290
host .87:   cx_connect_fail: (absent/0)   cx_total: 229   rq_success: 289   rq_timeout: 207   rq_total: 289

rq_success == rq_total on both hosts. rq_timeout is not subtracted from either — it is tracked as an independent, non-exclusive counter.

Cross-checked against the equivalent Prometheus stats (envoy_cluster_upstream_rq_completed, envoy_cluster_upstream_rq_timeout, envoy_cluster_upstream_rq{envoy_response_code=...}) over the same window:

• envoy_cluster_upstream_rq_completed == sum(envoy_cluster_upstream_rq) by response code, exactly, at every sampled timestamp — every completed request has a normal, successful response code (200, mostly). No unaccounted/uncoded completions.
• envoy_cluster_upstream_cx_connect_fail, ..._cx_connect_timeout, ..._cx_pool_overflow, ..._cx_idle_timeout, ..._rq_per_try_timeout, ..._rq_max_duration_reached, ..._rq_rx_reset, ..._rq_tx_reset are all zero for this cluster throughout the observation window.
• envoy_cluster_health_check_* does not exist for this cluster at all — no active health check is configured.
• histogram_quantile on envoy_cluster_upstream_rq_time_bucket shows p50/p90/p99 well under any configured timeout (single-digit-to-low-double-digit milliseconds at the median; a small tail up to a few seconds).
• No retry or hedge policy is configured on the route (confirmed via the live config_dump), so rq_timeout cannot be a per-try-timeout artifact of a retry we don't have.
• The route in question does have an explicit timeouts.request: 60s (via Gateway API HTTPRoute.spec.rules[].timeouts.request, Contour v1.28.0+) — adding this reduced the rate of the effect by roughly 2-3x but did not eliminate it, and did not change the qualitative pattern (still rq_success == rq_total with rq_timeout ticking independently).

What I've ruled out

• Retries/hedging inflating rq_timeout via per-try semantics — none configured.
• Connection pool exhaustion / stale pooled connections — all cx_* failure counters are zero.
• A downstream idle/stream-idle timeout mismatch — cx_idle_timeout is zero, and Contour's stream-idle-timeout default (5m) is far looser than the actual p99 latency (low seconds).
• Health-check-related eviction/probing — no health check exists on this cluster.
• Actual application-level failures — response-code accounting balances exactly with zero 5xx growth throughout multi-hour windows, including windows where the timeout ratio itself was 60-90%.

What I have NOT been able to determine

The exact internal code path that increments rq_timeout without the request otherwise appearing to fail. My working hypothesis, unconfirmed, is a race in the router filter between the per-request timer callback and the upstream response-decode callback — i.e. the timer fires (and increments the stat) at approximately the same instant the real response is already committed and gets forwarded downstream anyway — but I have not been able to prove this without Envoy-internal tracing/debug logging beyond what /stats and /clusters expose.

Reproduction

I don't yet have a minimal standalone repro (e.g. a bare Envoy config + toy upstream) — this is observed on a real Contour-managed deployment with the traffic characteristics described above (low/bursty request volume, plain HTTP/1.1, JSON-RPC-over-HTTP style requests with Connection: keep-alive, no retries configured, an explicit but generous route.timeout). If a maintainer can suggest what to instrument or which debug log level would isolate the code path (e.g. router or connection debug components), I'm happy to reproduce with that logging enabled and report back.

Ask

• Does anything in the router filter legitimately increment rq_timeout for a request that ultimately succeeds (e.g. a timer/response race, or a stat that's intentionally non-exclusive with rq_success)? If this is expected/documented behavior I've missed, a pointer would be appreciated.
• If not, any guidance on what to capture (debug log component/level, /stats more targeted) to pin the exact code path down further would let me turn this into a proper minimal repro.

[aleemshah-insignis]

Additional data point, since the ticket asked what to instrument: enabled router:debug,pool:debug,upstream:debug,connection:debug,http:debug,client:debug via the admin /logging endpoint (note: the query param is paths=, not level= — the latter fails silently and does not change anything, easy to mis-diagnose as "no output because nothing happened").

Captured 6 real requests to the affected cluster in a window where rq_timeout incremented twice (887→889→891 on the raw stat). Traced every one of the 6 by StreamId through the full router.cc/conn_manager_impl.cc lifecycle:

request headers complete -> router decoding headers -> pool ready
-> upstream headers complete -> encoding headers via codec -> Codec completed encoding stream

All six completed cleanly, sub-second to ~1.4s each, no gaps. No timeout-related log line appears anywhere in the capture — I grepped case-insensitively for "timeout" across the whole debug log and found only header values (x-envoy-expected-rq-timeout-ms) and an unrelated delayed close timer, never an actual timeout event (no per-try-timeout log, no request-timeout log, no reset).

So whatever increments rq_timeout here doesn't go through any code path that logs at debug on router, http, upstream, connection, pool, or client. That's stronger than the earlier stat-based elimination (which only showed the counters for those failure modes were zero) — this shows the corresponding log events for every request-timeout-adjacent code path I could enable didn't fire either, on requests I can independently confirm completed successfully and where the stat ticked in the same ~30s window.

Happy to enable further components (e.g. main, misc, or a wasm/filter-specific one) if there's a narrower code path you'd suggest — didn't want to guess further without a pointer given the number of possible components.