fix(proxy): keep backend latency for streaming sessions - #545
Conversation
The streaming carve-out returned from `record` before the upstream histogram was touched, so WebSocket and SSE sessions contributed no backend-latency sample at all. That was too broad: `upstream_ms` is measured at the first upstream response header — the `101`, or the SSE headers — before the tunnel starts carrying traffic, so it is a real latency even though the session's total duration is not. As written, a slow WebSocket handshake was invisible in `proxy.upstream_duration_*`. Streaming sessions now contribute to the backend histogram again. That required splitting the denominator: `proxy.self_duration_*` was dividing by `upstream_count`, and reusing it once streaming sessions land in the upstream histogram would drag the self-time mean toward zero — the same class of distortion this series was fixed to avoid, in the other direction. The self histogram gets its own `self_count`, and its gauges are emitted on that instead. Also documents what the carve-out does NOT catch — HTTP/2 WebSockets (RFC 8441 answers `200`, not `101`), gRPC streaming, chunked long-poll, and large or slow downloads all still land in the latency histograms — plus a per-series table of which observation set each gauge divides by, and a note that duration thresholds tuned before this series should be re-checked now that the values drop wherever streaming traffic exists. Follow-up to #514.
📓 Changelog previewThis is what your commits will add to the generated ## [Unreleased]
### Fixed
- **proxy:** Keep backend latency for streaming sessions
- **proxy:** Bound streaming handshake samples and tighten SSE detection |
Restoring the backend-latency sample for streaming sessions re-opened the distortion this series exists to close, aimed at a different gauge. `upstream_ms` is time-to-first-header, and `upstream_peer` grants a WebSocket upgrade a 1h read timeout — 60x the 60s ordinary traffic gets — chosen from the request's own `Upgrade` header. A hung upstream can therefore report a single ~3_600_000ms observation, which drags `proxy.upstream_duration_avg_ms` into the tens of seconds while every percentile stays flat, because at 1-in-100 the outlier sits above p99. Streaming handshakes are now clamped to `MAX_HANDSHAKE_OBSERVATION_MS` (60s, the ordinary read timeout), so a streaming session can move the backend mean no more than any other request already can. The observation is kept rather than dropped, so `upstream_count` stays honest. A test pins it: without the clamp the mean reads 35999.9ms instead of 609.9ms. Also tightens SSE classification. The upstream `content-type` was matched with `contains`, so `text/html; note=text/event-stream` qualified — and that header comes from a tenant's own app, while the flag it sets removes the request from the operator's latency histograms. Now compares the media type essence. The request-side `Accept` check deliberately stays a substring match, since `Accept` is a comma-separated list. Corrects the `record` doc, which still claimed streaming sessions were kept out of *every* duration histogram after they were added back to the backend one, and the stale relaxed-atomic-add counts in the same comment. Addresses the security-audit and review findings on this PR.
Review + security-audit fixes (
|
1 participant
Follow-up to #514, addressing the review findings on that PR.
1. Backend latency was over-excluded (the substantive fix)
#514's carve-out returned from
recordbefore the upstream histogram was touched, so a WebSocket or SSE session contributed no backend-latency sample. That was too broad.upstream_msis measured at the first upstream response header — the101, or the SSE headers — before the tunnel starts carrying traffic, so it is a genuine latency even though the session's total duration is not. As merged, a slow WebSocket handshake was invisible inproxy.upstream_duration_*.Streaming sessions now contribute to the backend histogram again.
This required splitting the denominator.
proxy.self_duration_*divided byupstream_count. Once streaming sessions land in the upstream histogram, reusing that count would drag the self-time mean toward zero — the same class of distortion #514 existed to fix, pointing the other way. The self histogram now carries its ownself_count.A regression test pins it. Reverting just the denominator gives:
2. Documented what the carve-out does not catch
#514 read as if it closed the whole class. It does not. Still landing in the latency histograms:
CONNECTanswers200, not101application/grpc), chunked long-poll / NDJSON feedselapsedcovers the whole body transferWidening detection would mean classifying on response duration rather than shape, which needs a threshold nobody can pick correctly for every deploy. The two covered cases are the ones that produce hour-long sessions by design; the rest are bounded by the upstream read timeout. That reasoning is now in the code rather than implied.
3. Per-series observation sets + operator note
The gauges do not all divide by the same number of requests, and nothing said so. Added a table to the module docs:
proxy.requests*,proxy.error_rate_percentproxy.request_duration_*proxy.upstream_duration_*proxy.self_duration_*proxy.streaming_*Plus an upgrade note: the duration series drop wherever streaming traffic exists, so alert thresholds tuned before #514 should be re-checked — one that used to fire may now sit permanently below its trigger.
4. Nits
skip_tracking.test_record_classifies_status_codesrecorded a101withis_streaming: false— a state the proxy cannot produce.Test plan
cargo test --lib -p temps-proxy— 449 passed, 0 failed.cargo clippy -p temps-proxy --all-targets -- -D warnings— clean.tsc --noEmit— clean.Not re-run: the live-proxy WebSocket/SSE exercise from #514. This change alters which histogram a sample lands in, not whether the session is detected, and the denominator split is covered by the unit test above.