Fix streaming-body watchdog bug (review #009 C2) + dead-upstream test wiring (C3)

C2: IdleTrackingService decremented in_flight when the handler returned
the Response, but for streaming responses (e.g. git clone) the body is
still in flight, so the watchdog could kill the connection mid-stream.
Fix: wrap the response body in IdleTrackingBody which owns the decrement,
releasing it on body EOF/error/drop (guarded against double-decrement by
an AtomicBool) and calling touch() on each data frame. The handler-level
decrement now only happens on the Err branch. Verified by a reproducer
test (streaming_body_not_killed_by_idle_watchdog) that streams 15 chunks
over 3s with a 500ms idle timeout — red on 4ab8c51, green with this fix.

C3: the two pre-existing idle-timeout tests pointed at 127.0.0.1:18080
where nothing listens, so they validated watchdog behaviour against an
immediate 504 error response (HTTP/1.1 prefix + in_flight==1 hold for
a 504 just as for a 200) and never exercised a real upstream round-trip.
Rewired them to spawn a real TestUpstream and assert HTTP/1.1 200 OK.
Removed the dead no-arg make_proxy_router/start_test_https_server wrappers.

Adds http-body as a direct dep (for the Frame/Body trait) and
tokio-stream as a dev-dep (for the slow-stream test helper).

cargo test: 226 unit + 40 integration green; cargo clippy --all-targets clean.

C1 (deploy to dev1) remains open and out of scope for this repo session.
This commit is contained in:
2026-08-19 09:48:13 +00:00
parent ff8819e950
commit 71ad3c2905
6 changed files with 366 additions and 23 deletions
Generated
+13
View File
@@ -1707,6 +1707,7 @@ dependencies = [
"dashmap",
"futures",
"hex",
"http-body",
"http-body-util",
"hyper",
"hyper-rustls",
@@ -1729,6 +1730,7 @@ dependencies = [
"thiserror 2.0.18",
"tokio",
"tokio-rustls",
"tokio-stream",
"toml",
"tower",
"tracing",
@@ -2293,6 +2295,17 @@ dependencies = [
"tokio",
]
[[package]]
name = "tokio-stream"
version = "0.1.17"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "eca58d7bba4a75707817a2c44174253f9236b2d5fbd055602e9d5c07c139a047"
dependencies = [
"futures-core",
"pin-project-lite",
"tokio",
]
[[package]]
name = "tokio-util"
version = "0.7.18"
+3 -1
View File
@@ -17,6 +17,7 @@ axum = "=0.8.9"
tokio = { version = "=1.45.1", features = ["full"] }
hyper = "=1.6.0"
hyper-util = { version = "=0.1.17", features = ["client-legacy", "http1", "http2", "tokio"] }
http-body = "=1.0.1"
http-body-util = "=0.1.3"
hyper-rustls = { version = "=0.27.9", features = ["http1", "http2"] }
rustls-native-certs = "=0.8.1"
@@ -47,4 +48,5 @@ hex = "0.4"
[dev-dependencies]
rcgen = "=0.13"
reqwest = { version = "=0.12", features = ["json"] }
tempfile = "=3.20"
tempfile = "=3.20"
tokio-stream = "=0.1.17"
@@ -9,9 +9,23 @@ reviewed_code:
reviewer: code-reviewer
based_on: docs/reviews/008-http2-keepalive-defeats-idle-timeout.md
trigger: Post-deployment observation — 9 days after review #008 fix was committed, production still shows the same idle-FD leak (433/1024 FDs, growing)
fixes:
- C2: FIXED in repo (commit pending) — IdleTrackingBody wrapper owns the
in_flight decrement until body EOF/drop; streaming reproducer test added
and passing.
- C3: FIXED in repo (commit pending) — existing idle-timeout tests rewired
to spawn a real upstream and assert a 200 round-trip instead of pointing
at a dead 127.0.0.1:18080.
- C1: NOT FIXED — deploy still pending (out of scope for this repo session).
---
# Follow-Up Review #009 — Fix for #008 Was Never Deployed + Streaming-Body Bug in the Fix
# Follow-Up Review #009 — Fix for #008 Was Never Deployed + Streaming-Body Bug in the Fix (+ dead-upstream test wiring)
> **Session update (2026-08-19):** C2 (streaming-body bug) and C3
> (dead-upstream test wiring, found during verification) are **fixed in
> the working tree** and verified by tests. C1 (deploy to dev1) remains
> open and out of scope for the repo session. See the Summary table for
> per-finding status.
## Purpose
@@ -120,7 +134,7 @@ sudo strings /usr/local/bin/reverse-proxy | grep -c "closing idle" # should be
---
## Finding C2: Watchdog decrements `in_flight` when the handler returns, not when the body finishes streaming [new code required]
## Finding C2: Watchdog decrements `in_flight` when the handler returns, not when the body finishes streaming [new code required] — VERIFIED + FIXED in repo
**Severity**: Critical for correctness — deploying the fix without
addressing this will trade the FD leak for intermittent broken large
@@ -128,6 +142,13 @@ transfers. Not a regression of the *current* production behavior (the
current binary has no watchdog at all), but a bug in the fix that would
become visible once C1 is deployed.
**Status (2026-08-19)**: Bug **verified empirically** with a reproducer
test, then **fixed** in `src/server.rs` with the `IdleTrackingBody`
wrapper (Option A from the recommended fix below). The reproducer test
`streaming_body_not_killed_by_idle_watchdog` now passes. Full suite green
(226 unit + 40 integration, clippy clean). C1 (deploy) is still pending
and out of scope for the repo-side fix session.
### The bug
`IdleTrackingService::call` in `src/server.rs:114-127`:
@@ -205,6 +226,14 @@ only keeps the connection "active" by making the idle timeout longer
than the test window — it does not exercise a long-running stream with
`in_flight == 0`.
**Correction (2026-08-19, during verification):** The reason is
actually worse than "buffered response" — see C3 below. The two tests
pointed at `127.0.0.1:18080`, where **nothing listens**, so they were
validating watchdog behaviour against an immediate 504 error response
(a `HTTP/1.1 ` status line and `in_flight == 1` hold just as well for
a 504 as a 200). They never exercised a real upstream round-trip at
all, buffered or otherwise.
### Recommended fix
The watchdog must consider a connection "active" while a response body
@@ -297,6 +326,77 @@ Add an integration test:
This test fails against the current `4ab8c51` code and passes with
Option A.
**Implemented (2026-08-19):** Added as
`tests/integration_test.rs::idle_timeout_tests::streaming_body_not_killed_by_idle_watchdog`.
Upstream emits 15 chunks every 200ms (3s total) via a new
`TestUpstream::spawn_slow_stream` helper; `idle_timeout = 500ms`. The
test asserts all 15 chunks arrive in order. Against `4ab8c51` it fails
after ~2 chunks (watchdog fires at ~500ms); with the `IdleTrackingBody`
fix it passes (all 15 chunks stream through). The fix in `src/server.rs`
follows Option A but reuses the single `in_flight` counter (the body's
decrement happens on EOF/drop via `IdleTrackingBody`, the handler's
decrement happens only on the `Err` branch — so a streaming `Response`
keeps `in_flight == 1` until the body finishes, which is exactly the
watchdog's idle condition). A `Drop` impl guards against double-decrement
(EOF then drop) with an `AtomicBool`.
---
## Finding C3: Existing idle-timeout tests point at a dead upstream (127.0.0.1:18080) [test hygiene] — VERIFIED + FIXED in repo
**Severity**: Medium — not a production bug, but a test-hygiene defect
that explains *why* C2 was never caught and that would have masked any
future regression of the watchdog against real traffic.
### The bug
`tests/integration_test.rs` (`make_proxy_router` / `start_test_https_server`
before this fix) hardcoded the test upstream as `127.0.0.1:18080`, but
**nothing spawns a listener there**. The two idle-timeout tests
(`idle_http1_connection_closed_after_timeout`,
`active_http1_connection_not_closed_within_timeout`) therefore hit an
immediate upstream **connection refused**, and the proxy returns a 504
error response. The tests then assert:
- `response.starts_with("HTTP/1.1 ")` — true for `HTTP/1.1 504 ...` just
as for `HTTP/1.1 200 OK`
- `in_flight.count() == 1` right after the response — true regardless of
status, since the connection is still open
- (for the "active" test) `n > 0` — true for the 504 body bytes
Both tests pass, but they have **never exercised a real upstream
round-trip**. They validate watchdog timing behaviour against an error
response, not a 200 from a live upstream — so they could not catch C2
even if they tried to stream.
### Why this matters
C2's "Why the tests don't catch it" section (above) attributed the miss
to "the test upstream returns immediately with a complete buffered
response." That is generous: the upstream returned immediately because
it didn't exist. The structural defect (no live upstream in the idle
test wiring) is what made the streaming blind spot possible — there was
never a mechanism in the test harness to point the proxy at a spawned
upstream, streaming or otherwise.
### Fix (implemented)
- Refactored `make_proxy_router``make_proxy_router_with_upstream(upstream)`
that takes the upstream address as a parameter.
- Refactored `start_test_https_server`
`start_test_https_server_with_upstream(idle_timeout, upstream)`.
- Both idle-timeout tests now spawn a real `TestUpstream::spawn_ok()`
upstream and assert `response.starts_with("HTTP/1.1 200 OK")` (a real
round-trip) instead of the loose `HTTP/1.1 ` prefix.
- The streaming reproducer (C2) uses the same wiring with
`TestUpstream::spawn_slow_stream`.
- Removed the dead no-arg wrappers (`make_proxy_router`,
`start_test_https_server`) since no caller needs the hardcoded
`18080` default anymore.
`cargo test` is green (226 unit + 40 integration); `cargo clippy
--all-targets` clean.
---
## Production data snapshot (2026-08-19 09:11 UTC)
@@ -352,18 +452,29 @@ should be closed only when the fix is verified in production. Leave as
## Summary
| ID | Issue | Severity | Action |
|----|-------|----------|--------|
| C1 | Review #008 fix never deployed — dev1 running pre-fix binary | Critical | Build fresh from HEAD (after C2 fix), deploy, verify |
| C2 | Watchdog decrements `in_flight` on handler return, not body-stream end → will kill large `git clone` | Critical (latent) | Wrap response body in `IdleTrackingBody` that owns the decrement; add streaming integration test |
| | Review #008 `status: open` despite "Closes" commit | Minor | Close after C1+C2 verified in production |
| ID | Issue | Severity | Action | Status |
|----|-------|----------|--------|--------|
| C1 | Review #008 fix never deployed — dev1 running pre-fix binary | Critical | Build fresh from HEAD (after C2 fix), deploy, verify | **Open** (deploy pending — out of scope for repo session) |
| C2 | Watchdog decrements `in_flight` on handler return, not body-stream end → will kill large `git clone` | Critical (latent) | Wrap response body in `IdleTrackingBody` that owns the decrement; add streaming integration test | **Fixed in repo** (commit pending); verified by reproducer test |
| C3 | Existing idle-timeout tests point at dead `127.0.0.1:18080` — never exercised a real upstream round-trip, so couldn't catch C2 | Medium (test hygiene) | Rewire tests to spawn a real upstream; assert `200 OK` | **Fixed in repo** (commit pending) |
| — | Review #008 `status: open` despite "Closes" commit | Minor | Close after C1+C2 verified in production | Open (unchanged) |
> Note: C2 and C3 are fixed in the working tree but **not yet committed**
> as of this writing — they will land in a single follow-up commit. C1
> (deploy) must still happen before this review can move to `closed`,
> since the leak is still live in production until the rebuilt binary is
> shipped to dev1.
## Recommended sequence for the fix session
1. **In this repo**: implement C2 (the `IdleTrackingBody` wrapper + guard
1. ~~**In this repo**: implement C2 (the `IdleTrackingBody` wrapper + guard
against double-decrement). Add the streaming-body integration test
described above. Run `cargo test` — expect the new test to pass and
existing tests to still pass.
existing tests to still pass.~~ **Done (2026-08-19).** C2 + C3 fixed,
`streaming_body_not_killed_by_idle_watchdog` reproducer added (red on
`4ab8c51`, green with fix), existing idle-timeout tests rewired to a
real spawned upstream. `cargo test` 226+40 green, `cargo clippy
--all-targets` clean. **Commit pending.**
2. **Build**: `cargo build --release` → produces a binary with both the
watchdog (from `4ab8c51`) and the streaming fix (new).
3. **Deploy to dev1**: copy binary, rebuild image, `docker compose up -d`.
+96 -4
View File
@@ -1,13 +1,17 @@
use std::net::SocketAddr;
use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering};
use std::sync::{Arc, Mutex};
use std::time::{Duration, Instant};
use std::future::Future;
use std::pin::Pin;
use std::task::{Context, Poll};
use axum::body::Body;
use axum::extract::ConnectInfo;
use axum::http::Request;
use axum::response::Response;
use axum::Router;
use http_body::Frame;
use hyper::body::Incoming;
use hyper_util::rt::TokioExecutor;
use hyper_util::service::TowerToHyperService;
@@ -95,6 +99,84 @@ struct IdleTrackingService<S> {
idle_state: Arc<IdleState>,
}
struct IdleTrackingBody<B> {
inner: Option<B>,
idle_state: Arc<IdleState>,
decremented: AtomicBool,
}
impl<B> IdleTrackingBody<B> {
fn new(inner: B, idle_state: Arc<IdleState>) -> Self {
Self {
inner: Some(inner),
idle_state,
decremented: AtomicBool::new(false),
}
}
fn release(&self) {
if !self.decremented.swap(true, Ordering::SeqCst) {
self.idle_state.in_flight.fetch_sub(1, Ordering::SeqCst);
self.idle_state.touch();
}
}
}
impl<B> Drop for IdleTrackingBody<B> {
fn drop(&mut self) {
self.release();
}
}
impl<B> http_body::Body for IdleTrackingBody<B>
where
B: http_body::Body + Unpin + Send + 'static,
{
type Data = B::Data;
type Error = B::Error;
fn poll_frame(
self: Pin<&mut Self>,
cx: &mut Context<'_>,
) -> Poll<Option<Result<Frame<Self::Data>, Self::Error>>> {
let this = self.get_mut();
let inner = match this.inner.as_mut() {
Some(b) => b,
None => return Poll::Ready(None),
};
match Pin::new(inner).poll_frame(cx) {
Poll::Ready(None) => {
this.release();
Poll::Ready(None)
}
Poll::Ready(Some(Err(e))) => {
this.release();
Poll::Ready(Some(Err(e)))
}
Poll::Ready(Some(Ok(frame))) => {
this.idle_state.touch();
Poll::Ready(Some(Ok(frame)))
}
Poll::Pending => Poll::Pending,
}
}
fn is_end_stream(&self) -> bool {
self.inner
.as_ref()
.map(|b| b.is_end_stream())
.unwrap_or(true)
}
fn size_hint(&self) -> http_body::SizeHint {
self.inner
.as_ref()
.map(|b| b.size_hint())
.unwrap_or_default()
}
}
impl<S> Service<Request<Incoming>> for IdleTrackingService<S>
where
S: Service<Request<Incoming>, Response = Response> + Clone + Send + 'static,
@@ -120,9 +202,19 @@ where
Box::pin(async move {
let result = inner_fut.await;
idle_state.in_flight.fetch_sub(1, Ordering::SeqCst);
idle_state.touch();
result
match result {
Ok(resp) => {
let (parts, body) = resp.into_parts();
let tracked = IdleTrackingBody::new(body, idle_state.clone());
let new_body = Body::new(tracked);
Ok(Response::from_parts(parts, new_body))
}
Err(e) => {
idle_state.in_flight.fetch_sub(1, Ordering::SeqCst);
idle_state.touch();
Err(e)
}
}
})
}
}
+32
View File
@@ -1,4 +1,5 @@
use std::net::SocketAddr;
use std::time::Duration;
use axum::routing::get;
use axum::Router;
@@ -34,4 +35,35 @@ impl TestUpstream {
pub async fn spawn_ok() -> Self {
Self::spawn(|| Router::new().route("/", get(|| async { "ok" }))).await
}
/// Upstream that emits one chunk every `chunk_interval` for `num_chunks`
/// chunks, then ends. The body stream outlasts the idle timeout so the
/// watchdog's behaviour for in-progress streaming responses is observable.
/// Emits `b"<n>"` per chunk so the client can verify it received the whole
/// stream.
pub async fn spawn_slow_stream(chunk_interval: Duration, num_chunks: usize) -> Self {
Self::spawn(move || {
let interval = chunk_interval;
let n = num_chunks;
Router::new().route(
"/",
get(move || async move {
let (tx, rx) = tokio::sync::mpsc::channel::<
Result<axum::body::Bytes, std::convert::Infallible>,
>(16);
tokio::spawn(async move {
for i in 0..n {
tokio::time::sleep(interval).await;
let _ = tx
.send(Ok(format!("<{i}>").into_bytes().into()))
.await;
}
});
let stream = tokio_stream::wrappers::ReceiverStream::new(rx);
axum::body::Body::from_stream(stream)
}),
)
})
.await
}
}
+102 -9
View File
@@ -995,14 +995,16 @@ mod idle_timeout_tests {
TlsAcceptor::from(Arc::new(server_config))
}
fn make_proxy_router() -> (
fn make_proxy_router_with_upstream(
upstream: String,
) -> (
Arc<reverse_proxy::proxy::ProxyState>,
Arc<ArcSwap<DynamicConfig>>,
Arc<reverse_proxy::rate_limit::RateLimiter>,
) {
let sites = vec![SiteConfig {
host: "test.local".to_string(),
upstream: "127.0.0.1:18080".to_string(),
upstream,
upstream_scheme: "http".to_string(),
upstream_connect_timeout_secs: 5,
upstream_request_timeout_secs: 60,
@@ -1028,8 +1030,9 @@ mod idle_timeout_tests {
(proxy_state, config_arc, rate_limiter)
}
async fn start_test_https_server(
async fn start_test_https_server_with_upstream(
idle_timeout: Duration,
upstream: String,
) -> (
std::net::SocketAddr,
Arc<InFlightCounter>,
@@ -1039,7 +1042,7 @@ mod idle_timeout_tests {
let listener = TcpListener::bind("127.0.0.1:0").await.unwrap();
let addr = listener.local_addr().unwrap();
let tls_acceptor = make_test_tls_acceptor();
let (proxy_state, config_arc, rate_limiter) = make_proxy_router();
let (proxy_state, config_arc, rate_limiter) = make_proxy_router_with_upstream(upstream);
let router = reverse_proxy::proxy::build_router(proxy_state, config_arc, rate_limiter);
let in_flight = InFlightCounter::new();
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(false);
@@ -1129,7 +1132,10 @@ mod idle_timeout_tests {
#[tokio::test]
async fn idle_http1_connection_closed_after_timeout() {
let idle_timeout = Duration::from_millis(500);
let (addr, in_flight, _handle, _shutdown_tx) = start_test_https_server(idle_timeout).await;
let upstream = helpers::http_test_helper::TestUpstream::spawn_ok().await;
let upstream_addr = format!("127.0.0.1:{}", upstream.addr.port());
let (addr, in_flight, _handle, _shutdown_tx) =
start_test_https_server_with_upstream(idle_timeout, upstream_addr).await;
let mut tls_stream = connect_tls(addr).await;
@@ -1145,8 +1151,8 @@ mod idle_timeout_tests {
.expect("read error");
let response = String::from_utf8_lossy(&buf[..n]);
assert!(
response.starts_with("HTTP/1.1 "),
"expected HTTP response, got: {response}"
response.starts_with("HTTP/1.1 200 OK"),
"expected a real 200 round-trip from the upstream, got: {response}"
);
tokio::time::sleep(Duration::from_millis(100)).await;
@@ -1180,12 +1186,17 @@ mod idle_timeout_tests {
0,
"in-flight count should be 0 after connection closed"
);
let _ = upstream.shutdown_tx.send(());
}
#[tokio::test]
async fn active_http1_connection_not_closed_within_timeout() {
let idle_timeout = Duration::from_secs(2);
let (addr, in_flight, _handle, _shutdown_tx) = start_test_https_server(idle_timeout).await;
let upstream = helpers::http_test_helper::TestUpstream::spawn_ok().await;
let upstream_addr = format!("127.0.0.1:{}", upstream.addr.port());
let (addr, in_flight, _handle, _shutdown_tx) =
start_test_https_server_with_upstream(idle_timeout, upstream_addr).await;
let mut tls_stream = connect_tls(addr).await;
@@ -1199,7 +1210,11 @@ mod idle_timeout_tests {
.await
.expect("timeout waiting for first response")
.expect("read error");
assert!(n > 0);
let response = String::from_utf8_lossy(&buf[..n]);
assert!(
response.starts_with("HTTP/1.1 200 OK"),
"expected a real 200 round-trip from the upstream, got: {response}"
);
let read_result = tokio::time::timeout(
idle_timeout / 2,
@@ -1217,5 +1232,83 @@ mod idle_timeout_tests {
1,
"connection should still be in-flight (active)"
);
let _ = upstream.shutdown_tx.send(());
}
// Reproducer for review #009 C2: a streaming response body that outlasts
// the idle timeout must NOT be killed mid-stream by the watchdog. The
// watchdog should only fire when no request is in flight AND no response
// body is still streaming. With the current code (commit 4ab8c51),
// `in_flight` is decremented when the handler returns the Response, not
// when the body finishes streaming, so this test is expected to FAIL.
#[tokio::test]
async fn streaming_body_not_killed_by_idle_watchdog() {
// Stream one chunk every 200ms for 3s total (15 chunks). The stream
// outlasts the 500ms idle timeout by 6x.
let chunk_interval = Duration::from_millis(200);
let num_chunks: usize = 15;
let idle_timeout = Duration::from_millis(500);
let upstream =
helpers::http_test_helper::TestUpstream::spawn_slow_stream(chunk_interval, num_chunks)
.await;
let upstream_addr = format!("127.0.0.1:{}", upstream.addr.port());
let (addr, _in_flight, _handle, _shutdown_tx) =
start_test_https_server_with_upstream(idle_timeout, upstream_addr).await;
let mut tls_stream = connect_tls(addr).await;
tls_stream
.write_all(b"GET / HTTP/1.1\r\nHost: test.local\r\nConnection: keep-alive\r\n\r\n")
.await
.unwrap();
// Read the response headers + as much body as the server sends before
// closing the connection (or before a generous test deadline).
let mut buf = Vec::new();
let deadline = tokio::time::Instant::now() + Duration::from_secs(15);
let mut tmp = [0u8; 4096];
loop {
let remaining = deadline.saturating_duration_since(tokio::time::Instant::now());
if remaining.is_zero() {
break;
}
match tokio::time::timeout(remaining, tls_stream.read(&mut tmp)).await {
Ok(Ok(0)) => break,
Ok(Ok(n)) => buf.extend_from_slice(&tmp[..n]),
Ok(Err(e)) if e.kind() == std::io::ErrorKind::UnexpectedEof => break,
Ok(Err(e)) => panic!("unexpected read error: {e:?}"),
Err(_) => break,
}
}
let response = String::from_utf8_lossy(&buf);
// The response must contain every chunk the upstream emitted, in
// order. If the watchdog killed the connection mid-stream, later
// chunks will be missing. We check for each chunk as a separate
// substring (in order) rather than a single contiguous string
// because HTTP chunked transfer-encoding interleaves frame
// delimiters ("\r\n3\r\n") between data chunks.
let mut search_from = 0;
for i in 0..num_chunks {
let needle = format!("<{i}>");
match response[search_from..].find(&needle) {
Some(pos) => search_from += pos + needle.len(),
None => {
panic!(
"streaming body was truncated — watchdog killed the connection mid-stream.\n\
missing chunk {i:?} ({needle:?}) after byte {search_from}.\n\
expected {num_chunks} chunks (<0>..<{n}>, n={n}).\n\
got: {response:?}",
n = num_chunks - 1,
);
}
}
}
let _ = upstream.shutdown_tx.send(());
}
}