envoyproxy / envoyproxy/envoy

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

Open
#46,665 2 comments 0 reactions 0 assignees View on GitHub
stale
Dominant language
C++
Stars
28.9k
Forks
5.6k
Avg merge
1d 22h
Merged PRs (30d)
430

Description

### 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.

Contributor guide

Open the contributing guide

Research direction

Start by reproducing the discrepancy with the `/clusters?format=json` and targeted `/stats` counters, then inspect the router and connection debug components suggested in the issue. Compare the timeout and success counters with the route timeout and live `config_dump`; done means identifying whether the counters are intentionally non-exclusive or isolating a reproducible router timer/response race.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp
Domain
backend, networking, observability
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Active
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.