diff --git a/crates/gateway/ARCHITECTURE.md b/crates/gateway/ARCHITECTURE.md index 14c06951..5bba15ac 100644 --- a/crates/gateway/ARCHITECTURE.md +++ b/crates/gateway/ARCHITECTURE.md @@ -1761,7 +1761,7 @@ Two more endings the provider bills and we used to write as zero get the same tr closes before its body's framing-defined end (bytes of a `Content-Length` still to come, a chunked body's last chunk missing) did not get it there, though pingora marks such a body done (`client_body_cut_short`, D259). A request that never reached a provider (every breaker open, a - connect failure, a reset mid-upload, the client closing mid-upload) stays + connect failure, a reset mid-upload, the client closing or stalling mid-upload) stays unbilled, and so does one the upstream **closed or reset** before any head (the gateway's 502): the peer declined to answer, and nothing says it processed the request. The real edges in front of Anthropic, OpenAI and OpenRouter answer a request they forwarded and then lost with an HTTP error @@ -2125,7 +2125,10 @@ the rate guardrails (which protect against abusive _inbound_ load): provider was waiting on the client: a stalled or abandoned upload. Neither counts. Before this, any caller, BYO included, could open a provider's breaker for every tenant with a few oversized or stalled uploads. A connect failure feeds no body byte, so it still counts. The cost: a provider - that resets the connection mid-upload is not blamed for it either; one that answers 5xx is. + that resets the connection mid-upload is not blamed for it either; one that answers 5xx is. A + stall's read timeout is retagged as the client's in `error_while_proxy` (D260, below), so a + catalog walk does not fail over either, which would have charged the candidate it left from + `upstream_peer`. - **Nor is either of those a success.** An attempt that ends with no provider outcome (no response head, and the error is the client's: an abort, a stalled or abandoned upload) gives its permit back without one (`CircuitBreaker::release`). Recording a success there closed a half-open breaker on a @@ -2430,6 +2433,24 @@ the one rule, and a small body is read straight through to the upstream (nothing connecting), so "the client's body was read" tracks what went out. A timeout is never resent: it is a liveness verdict on a peer that may have the request. +**A client that stalls mid-upload times out its own request.** A client that stops sending its +body with the connection still open leaves a provider waiting for bytes that never come, until the +upstream read timeout fires. That is the client's stall, not a provider failure, so it must not +fail over (the next candidate would wait on the same missing bytes), charge a breaker, or bill an +estimate. Pingora's upstream half waits on the response and the next body chunk at once and +re-arms the read timeout on each chunk, and a body write blocked on an upstream that stopped +reading is a `WriteTimedout` instead, so a `ReadTimedout` while the client still owes body bytes +(`client_stalled_upload`: some fed, `is_body_done` false) means nothing moved either way for +`read_timeout_secs` with the provider waiting on the client. `error_while_proxy` retags it as a +downstream error (D260): the walk ends with no failover, `logging` gives the breaker permit back, +`body_delivered` is false so nothing is billed (`outcome: client_cancelled`), and `fail_to_proxy` +answers 408 (`request body timed out`), the same answer as pingora's own HTTP/1.1 body read +timeout (60s, which wins over the default 600s `read_timeout_secs` on HTTP/1.1). Pingora's HTTP/2 +server has no body read timeout, so for an h2c client the upstream read timeout is the only clock. +An HTTP/2 upstream connection is still marked for shutdown on that timeout (pingora does so before +the hook runs). A chunked body on a catalog walk is read whole before connecting, so its stall is +pingora's downstream 408 and never reaches a provider. + **A pooled connection reset with the request unread is not delivered.** A **reused** HTTP/1.1 connection reset before any response byte means the provider's kernel answered with RST because the socket was closed with our request unread in it: the idle-close race on a pooled connection, which @@ -2878,6 +2899,7 @@ already gone gets nothing, and a response that has started cannot be replaced. | Provider TCP connect fails | `fail_to_connect` retries up to 2×, then returns a JSON 502. Counts as a circuit-breaker failure. | Client SDK retries with backoff. No HTTP-status retries (Pingora-idiomatic). | | Provider connection dies (host gone, partition, wedged edge) | Upstream HTTP/2 PING goes unacknowledged → the connection and its streams fail within `h2_ping_interval_secs` + 5s (≤ 20s); on HTTP/1.1, TCP keepalive drops the peer within 30s (and `TCP_USER_TIMEOUT` fails unacknowledged request bytes as fast). Before the head: a JSON 502; mid-stream: the client gets an error, never a clean end, and the row is `cut_short`. | Client retry. | | Provider alive but silent (no head yet, or a quiet gap: a model thinking without emitting) | Never cut before `read_timeout_secs` (600s), the clients' own default timeout: the gateway cannot tell thinking from stuck, so it does not guess. Then a JSON 504 (`upstream timed out after receiving the request`), not resent. No total deadline: a stream that keeps sending lives until it ends. A row whose vendor documents requests taking "several minutes" and publishes no maximum (OpenAI's `-pro` models, `catalog::long_running`) has no silence deadline at all (D252): it ends at the client's timeout (a cancel, billed per D130) or a dead transport. | Client timeout or retry. | +| Client stalls mid-upload (stops sending, connection open) | Ends at the first body read timeout: pingora's HTTP/1.1 one (60s), or `read_timeout_secs` on the upstream (the only clock for h2c). Either way a JSON 408 (`request body timed out`), the client's own timeout: no failover, no breaker failure, no key cooled, nothing billed (D260). | Client retry, which is a fresh request. `tests/cancellation.rs` pins it over HTTP/1.1, h2c and chunked. | | Provider brownout (sustained 5xx) | After `circuit_breaker_threshold` 5xx/connect failures in the window that are also at least half its outcomes (so a 50% brownout counts), the breaker opens; requests fast-fail 503 (`circuit_open`) instead of stalling against the read timeout. | Auto: after `circuit_breaker_reset_secs` a half-open probe is admitted — success closes the breaker, failure reopens it. Per-provider, so other providers are unaffected. | | Provider throttles (429 storm) | Walk the next unused pool key on the same provider when the body is replayable; the last 429 is relayed with `Retry-After` if the upstream sent one. Does **not** trip the breaker (provider is healthy). Does **not** fail over to another vendor. | Client `Retry-After` backoff after keys are exhausted; no gateway-side circuit action. | | Pool key out of credit (a credit-balance 400, `insufficient_quota`) | Relayed with a neutral message (the head is relayed before the body says why), the key cooled off for 60s (`ai_key_auth_failures_total{reason="unfunded"}`); a catalog walk leaves the provider out while all its keys cool, so later requests go to the row's next candidate (D180). A `402` a catalog walk fails over on is served by the next candidate and cools the key at the head, except OpenRouter's (D258). Not a breaker failure. | Fund the account or replace the key; the warn line `pool key is out of credit` names provider and key index. | diff --git a/crates/gateway/src/proxy.rs b/crates/gateway/src/proxy.rs index d254724f..21215c1b 100644 --- a/crates/gateway/src/proxy.rs +++ b/crates/gateway/src/proxy.rs @@ -2257,6 +2257,18 @@ fn client_still_uploading(session: &mut Session, rc: &RequestCtx) -> bool { rc.body_bytes_fed > 0 && !session.as_mut().is_body_done() } +/// Whether the upstream's read timeout fired while the client still owed body bytes (D260): the +/// client stalled mid-upload with its connection open. Pingora's upstream half waits on the +/// response and on the next body chunk at once, re-arming the read timeout on each chunk, and a +/// body write blocked on an upstream that stopped reading is a `WriteTimedout` instead; so this +/// timeout means neither side moved a byte for `read_timeout_secs`, with the provider waiting on +/// the client. Zero bytes fed is excluded as [`client_still_uploading`] excludes it: a client +/// that sent `Expect: 100-continue` waits on the provider's answer before its first byte. Any +/// source: pingora's own downstream body read timeout (HTTP/1.1, 60 s) is already the client's. +fn client_stalled_upload(session: &mut Session, rc: &RequestCtx, e: &pingora_core::Error) -> bool { + e.etype() == &pingora_core::ErrorType::ReadTimedout && client_still_uploading(session, rc) +} + /// The lowest set bit in `usable` at or after index `from`, or `None` if there is none. /// /// The candidate walk's only cursor primitive. `from` strictly increases across a request, so the @@ -6068,6 +6080,17 @@ impl ProxyHttp for AiProxy { if matches!(e.etype(), T::HTTPStatus(_) | T::CustomCode(..)) { return e; } + // A client that stalled mid-upload timed its own request out (D260): retag the timeout as + // the client's, so the walk below ends here rather than failing over with a body nobody + // will finish, `logging` charges no breaker and bills no estimate, and `fail_to_proxy` + // answers 408 rather than blaming the provider with a 504. + if ctx + .rc + .as_ref() + .is_some_and(|rc| client_stalled_upload(session, rc, &e)) + { + e.as_down(); + } // One rule for every body size (D09, D51): a connection failure is retried only when the // upstream cannot have the whole request (`body_delivered` is false: the connection never // came up, the body was not read to its end, or writing it failed), and never once the diff --git a/crates/gateway/tests/cancellation.rs b/crates/gateway/tests/cancellation.rs index e5e1c43c..dbca1424 100644 --- a/crates/gateway/tests/cancellation.rs +++ b/crates/gateway/tests/cancellation.rs @@ -533,3 +533,208 @@ async fn a_read_timeout_on_a_reused_connection_is_not_resent() { tokio::time::sleep(Duration::from_millis(300)).await; assert_eq!(mock.hits(), 2, "{text}\nlog:\n{}", gw.log()); } + +/// Send `head` and then `sent` (the start of a body whose rest never comes) on a raw HTTP/1.1 +/// connection that stays open, and return the gateway's answer (status line and all). +async fn h1_stalled_upload(port: u16, head: &str, sent: &str) -> String { + use tokio::io::{AsyncReadExt, AsyncWriteExt}; + let mut s = tokio::net::TcpStream::connect(("127.0.0.1", port)) + .await + .unwrap(); + s.write_all(head.as_bytes()).await.unwrap(); + s.write_all(sent.as_bytes()).await.unwrap(); + let mut buf = [0u8; 4096]; + let n = tokio::time::timeout(Duration::from_secs(10), s.read(&mut buf)) + .await + .expect("an answer") + .unwrap_or(0); + String::from_utf8_lossy(&buf[..n]).into_owned() +} + +/// The same over h2c: one stream whose headers declare `content-length` and whose single DATA +/// frame carries only `sent`, the stream left open. Returns the status and the response body. +async fn h2_stalled_upload(port: u16, headers: &[(&str, String)], sent: &str) -> (u16, String) { + let tcp = tokio::net::TcpStream::connect(("127.0.0.1", port)) + .await + .unwrap(); + let (mut client, conn) = h2::client::handshake(tcp).await.unwrap(); + tokio::spawn(conn); + let mut req = http::Request::post("http://gw/auto/chat/completions"); + for (k, v) in headers { + req = req.header(*k, v.as_str()); + } + let (resp, mut send) = client.send_request(req.body(()).unwrap(), false).unwrap(); + send.send_data(bytes::Bytes::copy_from_slice(sent.as_bytes()), false) + .unwrap(); + let resp = tokio::time::timeout(Duration::from_secs(10), resp) + .await + .expect("an answer") + .unwrap(); + let status = resp.status().as_u16(); + let mut body = resp.into_body(); + let mut text = Vec::new(); + while let Some(chunk) = body.data().await { + let Ok(chunk) = chunk else { break }; + let _ = body.flow_control().release_capacity(chunk.len()); + text.extend_from_slice(&chunk); + } + drop(send); + (status, String::from_utf8_lossy(&text).into_owned()) +} + +/// A managed client that stalls mid-upload, connection open, ends its own request: the upstream's +/// read timeout fires on a provider still waiting for the client's bytes, which is the client's +/// stall, not the provider failing (D260). So the walk does not fail over to the next candidate, +/// the candidate's breaker hears nothing (the next request still reaches it, with a threshold of +/// 1), no pool key is cooled, the client gets a 408, and the half a provider was sent is not +/// billed. +/// +/// Over HTTP/1.1 and h2c, each a `Content-Length` body with bytes still to come. h2c is the shape +/// that reaches this in production: pingora's HTTP/2 server has no body read timeout, so the +/// upstream's `read_timeout_secs` is the only clock on a stalled stream. Over HTTP/1.1 pingora's +/// own 60 s body read timeout (a 408) wins against the default 600 s; this one runs at 1 s. A +/// chunked body cannot stall here: with no declared length a catalog walk reads the whole body +/// before it connects (see the chunked test below for one that streams). +/// claim: REL-1, SEC-16, BIL-3 +/// defect: D260 +#[tokio::test] +async fn a_client_stalled_mid_upload_is_not_failed_over() { + use std::sync::atomic::Ordering::SeqCst; + let payload = body(); + let half = &payload[..payload.len() / 2]; + for h2 in [false, true] { + let what = if h2 { "h2c" } else { "http/1.1" }; + let (primary, primary_conns) = silent_upstream().await; + let (fallback, fallback_conns) = silent_upstream().await; + let (pubkey, sk) = test_keypair(1); + let gw = Gateway::builder( + unused_nats_port(), + &format!("127.0.0.1:{primary}"), + &b64(&pubkey), + ) + .providers(&["openai", "openrouter"]) + .provider_authority("openrouter", &format!("127.0.0.1:{fallback}")) + .config_line("read_timeout_secs = 1") + .config_line("circuit_breaker_threshold = 1") + .config_line("circuit_breaker_window_secs = 60") + .config_line("circuit_breaker_reset_secs = 60") + .start() + .await; + let vkey = billing_vkey(&sk, 260); + let headers = [ + ("authorization", format!("Bearer {vkey}")), + ("content-type", "application/json".to_owned()), + ("x-beyond-model", "gpt-4o-mini".to_owned()), + ("x-beyond-order", "openai,openrouter".to_owned()), + ("content-length", payload.len().to_string()), + ]; + let (status, text) = if h2 { + h2_stalled_upload(gw.port, &headers, half).await + } else { + let mut head = "POST /auto/chat/completions HTTP/1.1\r\nhost: gw\r\n".to_owned(); + for (k, v) in &headers { + head.push_str(&format!("{k}: {v}\r\n")); + } + head.push_str("\r\n"); + let text = h1_stalled_upload(gw.port, &head, half).await; + let status = text + .strip_prefix("HTTP/1.1 ") + .and_then(|t| t.get(..3)) + .and_then(|s| s.parse().ok()) + .unwrap_or(0); + (status, text) + }; + assert_eq!(status, 408, "{what}: {text}\nlog:\n{}", gw.log()); + assert!(text.contains("request body timed out"), "{what}: {text}"); + let row = usage_row_of(&gw).await; + assert_eq!(row["usage_estimated"], false, "{what}: {row}"); + assert_eq!(row["input_tokens"].as_u64(), Some(0), "{what}: {row}"); + assert_eq!(row["outcome"], "client_cancelled", "{what}: {row}"); + // With a threshold of 1, a failure charged to the primary would have opened its breaker + // and sent this request to the fallback. + let resp = reqwest::Client::new() + .post(format!("{}/auto/chat/completions", gw.url())) + .header("authorization", format!("Bearer {vkey}")) + .header("content-type", "application/json") + .header("x-beyond-model", "gpt-4o-mini") + .header("x-beyond-order", "openai,openrouter") + .body(payload.clone()) + .send() + .await + .unwrap(); + assert_eq!(resp.status().as_u16(), 504, "{what}"); + assert_eq!( + (primary_conns.load(SeqCst), fallback_conns.load(SeqCst)), + (2, 0), + "{what}: log:\n{}", + gw.log() + ); + let metrics = gw.metrics().await; + assert_eq!( + parse_metric(&metrics, "ai_candidate_failovers_total", ""), + 0.0, + "{what}" + ); + for reason in ["revoked", "unfunded", "key_named_403"] { + assert_eq!( + parse_metric(&metrics, "ai_key_auth_failures_total", reason), + 0.0, + "{what}: {reason}" + ); + } + } +} + +/// A managed chunked upload that stalls mid-stream on a provider route (which streams the body: +/// no catalog walk reads it first) times out as the client's own: a 408, its breaker charged +/// nothing (the next request still reaches the provider, with a threshold of 1), and not billed. +/// claim: REL-1, SEC-16, BIL-3 +/// defect: D260 +#[tokio::test] +async fn a_client_stalled_mid_chunked_upload_times_out_as_its_own() { + use std::sync::atomic::Ordering::SeqCst; + let (upstream, conns) = silent_upstream().await; + let (pubkey, sk) = test_keypair(1); + let gw = Gateway::builder( + unused_nats_port(), + &format!("127.0.0.1:{upstream}"), + &b64(&pubkey), + ) + .config_line("read_timeout_secs = 1") + .config_line("circuit_breaker_threshold = 1") + .config_line("circuit_breaker_window_secs = 60") + .config_line("circuit_breaker_reset_secs = 60") + .start() + .await; + let vkey = billing_vkey(&sk, 261); + let payload = body(); + let half = &payload[..payload.len() / 2]; + let head = format!( + "POST /openai/v1/chat/completions HTTP/1.1\r\nhost: gw\r\nauthorization: Bearer {vkey}\r\n\ + content-type: application/json\r\ntransfer-encoding: chunked\r\n\r\n", + ); + let text = h1_stalled_upload(gw.port, &head, &format!("{:x}\r\n{half}\r\n", half.len())).await; + assert!( + text.starts_with("HTTP/1.1 408"), + "{text}\nlog:\n{}", + gw.log() + ); + let row = usage_row_of(&gw).await; + assert_eq!(row["usage_estimated"], false, "{row}"); + assert_eq!(row["input_tokens"].as_u64(), Some(0), "{row}"); + assert_eq!(row["outcome"], "client_cancelled", "{row}"); + let resp = reqwest::Client::new() + .post(format!("{}/openai/v1/chat/completions", gw.url())) + .header("authorization", format!("Bearer {vkey}")) + .header("content-type", "application/json") + .body(payload.clone()) + .send() + .await + .unwrap(); + assert_eq!( + resp.status().as_u16(), + 504, + "the breaker opened on a client's stall" + ); + assert_eq!(conns.load(SeqCst), 2, "log:\n{}", gw.log()); +} diff --git a/verify/defects.toml b/verify/defects.toml index cf452788..c19e1f91 100644 --- a/verify/defects.toml +++ b/verify/defects.toml @@ -2583,3 +2583,17 @@ state = "fixed" test = "a_client_that_closes_mid_upload_is_not_billed_an_estimate" fix = "28bc659" note = "Fixed: body_delivered also requires that the error is not a downstream premature close (client_body_cut_short, matched on pingora's context strings through the cause chain, as h2_body_unsent matches its own; pingora's session API exposes no body_complete). Covers both framings; error_while_proxy's Downstream early return already kept such a request from being resent. A client that sends its whole body and then gives up is still billed (D130). HTTP/2 downstream resets are a different error and were not affected." + +[[defect]] +id = "D260" +severity = "low" +area = "Reliability" +title = "A client that stalled mid-upload was failed over to the next candidate, charging the one it left" +impact = "A managed client that stopped sending its body with the connection still open (an agent process paused, a stuck pipe) ended at the upstream read timeout as a provider failure: a catalog walk failed over to the next candidate with a body nobody would finish (which then waited out its own timeout), upstream_peer charged the candidate it left a breaker failure (one stall per window opens it at threshold 1, and enough of them at any threshold open it for every tenant), and the client got a 504 blaming the provider. h2c clients reach this at the default 600s, since pingora's HTTP/2 server has no body read timeout; HTTP/1.1 ones when read_timeout_secs is below pingora's own 60s body read timeout (a downstream 408 that already behaved). No pool key was cooled and nothing was billed (body_delivered needs is_body_done), and a provider route already kept its breaker clean (logging's client_still_uploading)." +confidence = "high" +evidence = "Hermetic (cancellation.rs, read_timeout_secs = 1, primary and fallback both silent listeners): half a Content-Length body to /auto with x-beyond-order openai,openrouter, connection held open -> after ~2s a 504 'upstream timed out', primary and fallback each accepted one connection; the same over h2c. error_while_proxy saw Upstream ReadTimedout with body_delivered false (is_body_done false), so a small replayable body took the walk's failover arm. pingora-proxy 0.9 proxy_h1.rs proxy_handle_upstream: read_response_task and rx.recv() share one select loop, so the read timeout re-arms on every body chunk, and send_body_to1 blocking on an upstream that stopped reading runs under write_timeout (WriteTimedout). Recorded as unfixed by the PR #121 triage agent." +claims = ["REL-1", "SEC-16", "BIL-3"] +state = "fixed" +test = "a_client_stalled_mid_upload_is_not_failed_over" +fix = "3e5c0d3" +note = "Fixed: error_while_proxy retags a ReadTimedout while the client still owes body bytes (client_stalled_upload: body_bytes_fed > 0 and !is_body_done, any source) as a downstream error before the delivered/failover decision. The walk ends with no failover, logging releases the breaker permit, body_delivered stays false (no estimate, outcome client_cancelled), and fail_to_proxy answers 408 'request body timed out', the same answer as pingora's HTTP/1.1 body read timeout. Zero bytes fed is excluded (an Expect: 100-continue client waits on the provider). Error path only. Not changed: pingora marks an HTTP/2 upstream connection for shutdown on any upstream read timeout before the hook runs. A chunked body on a catalog walk is read whole before connecting, so its stall is pingora's downstream 408; a_client_stalled_mid_chunked_upload_times_out_as_its_own pins a streamed chunked stall on a provider route."