diff --git a/crates/gateway/ARCHITECTURE.md b/crates/gateway/ARCHITECTURE.md index d487975f..9f1de94e 100644 --- a/crates/gateway/ARCHITECTURE.md +++ b/crates/gateway/ARCHITECTURE.md @@ -2361,6 +2361,18 @@ Two deliberate non-cases, plus one same-provider retry: holds for a provider whose keys all drew a `401`. A provider with several keys that are all out of credit is cooled one key per relayed answer (a key walk abandons the earlier keys' bodies unread). +- **A `402` the walk fails over on cools its key at the head, except on OpenRouter (D258).** A + failover abandons the response at its head (pingora's in-place retry and a `FullBody` re-run + alike), so `Redact` never reads that body and the rule above never ran: every later request paid + a round trip to the unfunded provider before failing over. Pingora's hooks give no way to read the + abandoned body, so the status decides: a `402` is out of credit by its status alone on every + provider but OpenRouter (`remedy::unfunded_402`), and the walk cools that key as `logging` would + (same metric, same warn line) before moving on. OpenRouter's `402` may be one request larger than + the balance ("This request requires more credits"), which must not cool a shared key (D180, D200), + so an OpenRouter `402` the walk fails over on cools nothing; one it relays (OpenRouter last in the + row, as it is unless the row leads with it or `x-beyond-order` puts it first) is read and cooled + as above. An abandoned `FullBody` attempt never cools from its body in `logging`, so a body that + raced the parent's drop is not counted twice. No work on any other status. - **When every candidate 5xxes, the client gets the last provider's own status**, not a synthetic error. Better diagnostics than an exhausted retry loop produces. @@ -2865,7 +2877,7 @@ already gone gets nothing, and a response that has started cannot be replaced. | 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. | | 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). 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. | +| 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. | | Pool key revoked (401) | Walk the next pool key on the same provider when the body is replayable, and cool the refused key off for 60s so later requests start on a good one (`ai_key_auth_failures_total{reason="revoked"}`; a 403 naming the key counts as `key_named_403`). The last key's 401 is relayed on a provider route, a candidate failure on a catalog walk. A 403 never walks or cools (a catalog walk fails over on it), except that one whose body names the key cools it. Not a breaker failure. | Replace the key in config; the metric says which provider (log line names the key index). | | Response body > 128KB before usage chunk | Tail compaction fires: `drain(..half)` discards first half, keeps tail. Usage extracted from retained tail. | No action — SSE usage is always in the final `data:` line, which always lands in the tail. | | Client cancels mid-request (ESC on a slow turn) | Relayed as a downstream abort. **Not** counted against the provider's breaker — pingora tags it `ErrorSource::Downstream`. A streaming 2xx cut short this way is billed an estimate (`usage_estimated=true`), not zero. The tenant slot is released. | None. `tests/cancellation.rs` pins the breaker halves; `tests/cut_short.rs` the billing. | diff --git a/crates/gateway/src/proxy.rs b/crates/gateway/src/proxy.rs index 622c10da..26ff2479 100644 --- a/crates/gateway/src/proxy.rs +++ b/crates/gateway/src/proxy.rs @@ -895,8 +895,10 @@ fn is_pool_key_failure(status: u16) -> bool { /// failure. Only a 401 ([`is_pool_key_failure`]) walks keys, and cools its key at the head. A /// relayed answer can cool its key from `logging` too, read from the body: a 403 that names the /// key ([`body_names_the_key`]), and an out-of-credit answer under any status (a 402, Anthropic's -/// credit-balance 400, OpenAI's `insufficient_quota` 429: `remedy::Neutralized::unfunded`). Each -/// is counted on `ai_key_auth_failures_total` by reason (`metrics::KeyCooled`). +/// credit-balance 400, OpenAI's `insufficient_quota` 429: `remedy::Neutralized::unfunded`). A 402 +/// the walk fails over on is abandoned at its head, body unread, so its key is cooled there when +/// the status alone says out of credit (`remedy::unfunded_402`, D258). Each is counted on +/// `ai_key_auth_failures_total` by reason (`metrics::KeyCooled`). fn is_candidate_refusal(status: u16) -> bool { (401..=403).contains(&status) } @@ -1704,6 +1706,21 @@ impl AiProxy { .await } + /// Cool this attempt's pool key because its account is out of credit (D180): later requests + /// start past it, and a catalog walk leaves the provider out once all its keys cool. Waiting + /// does not fix it, so it is cooled as a 401 is. + fn cool_unfunded_key(&self, request_id: &RequestId, provider: &Provider, key: u8, status: u16) { + self.state.metrics.key_cooled(KeyCooled::Unfunded); + warn!( + %request_id, + provider = provider.name.as_str(), + key, + status, + "pool key is out of credit; cooling it", + ); + provider.mark_key_bad(key); + } + /// Resolve a 2xx's pending health verdict from the first response bytes: count an /// error-in-200 against the candidate's breaker. fn settle_health(&self, rc: &mut RequestCtx, chunk: &[u8], end_of_stream: bool) { @@ -5023,6 +5040,18 @@ impl ProxyHttp for AiProxy { if first_usable(usable, at.saturating_add(1)).is_none() { return Ok(()); } + // Failing over abandons this response at its head, so `Redact` never reads the body that + // tells `logging` an account is out of credit (D180), and every later request would pay a + // round trip to it first. A 402 says so by its status alone except on OpenRouter, whose + // 402 may be one request too large for the balance (`remedy::unfunded_402`): cool that key + // here, as `logging` would have, on either abandoning path below (D258). + let unfunded = key_failure + && status == 402 + && rc + .auto + .as_ref() + .and_then(|a| a.candidate_at(at)) + .is_some_and(|c| remedy::unfunded_402(c.provider)); // Fail over only when the body is **provably** replayable: fully read, and small enough // that pingora buffered all of it. // @@ -5056,6 +5085,10 @@ impl ProxyHttp for AiProxy { "upstream returned {status}; re-running the full body on the next candidate", ); rc.relay_abandoned = fb.record(RelayRetry::Candidate(orig)); + // Not recorded (the final attempt): this answer is relayed and `logging` reads it. + if unfunded && rc.relay_abandoned { + self.cool_unfunded_key(&rc.request_id, &rc.provider, rc.pool_key, status); + } return Ok(()); } if !body_replayable(session) { @@ -5088,6 +5121,9 @@ impl ProxyHttp for AiProxy { { b.record_success_for(permit); } + if unfunded { + self.cool_unfunded_key(&rc.request_id, &rc.provider, rc.pool_key, status); + } rc.advance_candidate(at); let mut e = pingora_core::Error::new(pingora_core::ErrorType::HTTPStatus(status)); e.set_retry(true); @@ -6448,17 +6484,12 @@ impl ProxyHttp for AiProxy { // credit-balance 400, OpenAI's insufficient_quota 429: read from the body by `Redact`) // is that key refused until someone pays, which waiting does not fix. Cool it as a 401 // is cooled: later requests start past it, and a catalog walk leaves the provider out - // once all its keys cool (D180). This request already answered. - if rc.managed && rc.redact.as_ref().is_some_and(|r| r.unfunded) { - self.state.metrics.key_cooled(KeyCooled::Unfunded); - warn!( - request_id = %rc.request_id, - provider = rc.provider.name.as_str(), - key = rc.pool_key, - status = rc.upstream_status.unwrap_or(0), - "pool key is out of credit; cooling it", - ); - rc.provider.mark_key_bad(rc.pool_key); + // once all its keys cool (D180). This request already answered. Not an abandoned + // `FullBody` attempt: its body never reaches the client and is read only if it raced + // the parent's drop, and a walk's 402 was already judged at the head (D258). + if rc.managed && !rc.relay_abandoned && rc.redact.as_ref().is_some_and(|r| r.unfunded) { + let status = rc.upstream_status.unwrap_or(0); + self.cool_unfunded_key(&rc.request_id, &rc.provider, rc.pool_key, status); } // Extract usage facts (shape depends on dialect + streaming). Every case reads the tail; // Anthropic streaming *additionally* reads the head, because that's where `message_start` diff --git a/crates/gateway/src/remedy.rs b/crates/gateway/src/remedy.rs index 36d2b6de..3c3f3505 100644 --- a/crates/gateway/src/remedy.rs +++ b/crates/gateway/src/remedy.rs @@ -105,6 +105,14 @@ const XAI_NO_CREDIT: (&str, &str) = ( /// the key. Anchored at the start, which is OpenRouter's own text. const OPENROUTER_TOO_COSTLY: &str = "This request requires more credits"; +/// Whether a `402` from `provider` says the account is out of credit by its status alone, as +/// [`unfunded`] decides from the body: every provider's but OpenRouter's, whose `402` may instead +/// be one request too large for the balance ([`OPENROUTER_TOO_COSTLY`]). For a catalog walk that +/// fails over on the response head and so never reads the body (D258). +pub fn unfunded_402(provider: providers::ProviderId) -> bool { + provider != providers::ProviderId::OpenRouter +} + /// OpenRouter error metadata that describes Beyond's account with it, not the error. const ACCOUNT_METADATA: &[&str] = &["is_byok", "limit_source", "remedy_hint"]; @@ -457,4 +465,14 @@ mod tests { assert_eq!(v["error"]["message"], UNAVAILABLE, "{body}"); } } + + /// A walk that fails over on a 402 judges it by status and provider (D258): out of credit + /// everywhere except OpenRouter, the one provider whose 402 can be one request too costly. + #[test] + fn only_openrouter_needs_the_body_of_a_402() { + use providers::ProviderId; + for id in ProviderId::ALL { + assert_eq!(unfunded_402(id), id != ProviderId::OpenRouter, "{id:?}"); + } + } } diff --git a/crates/gateway/tests/reliability_unfunded_key.rs b/crates/gateway/tests/reliability_unfunded_key.rs index 92402dbe..3846abf6 100644 --- a/crates/gateway/tests/reliability_unfunded_key.rs +++ b/crates/gateway/tests/reliability_unfunded_key.rs @@ -261,3 +261,95 @@ async fn an_unfunded_candidate_cools_off_from_any_catalog_slot() { "OpenRouter was tried after it said it had no quota" ); } + +/// A catalog walk fails over on a 402 at the response head (D84), so the body `logging` reads to +/// cool an out-of-credit key (D180) is never read. Anthropic's `billing_error` 402 says out of +/// credit by its status alone, so the walk cools the key there: the first request is served by the +/// next candidate, and every request after it, for the cooldown, goes straight to it. OpenRouter's +/// 402 can instead be one request larger than the balance ("This request requires more credits"), +/// which a smaller request is not: that one fails over too, and cools nothing, so OpenRouter keeps +/// getting the row's requests. Both hold for a body pingora replays and for one past its 64 KiB +/// retry buffer, which fails over by a `FullBody` re-run. +/// claim: REL-4 +/// defect: D258 +#[tokio::test] +async fn a_402_the_walk_fails_over_on_cools_an_unfunded_key() { + const ANTHROPIC_BILLING: &str = r#"{"type":"error","error":{"type":"billing_error","message":"Your credit balance is too low to access the Anthropic API. Please go to Plans & Billing to upgrade or purchase credits."}}"#; + const OPENROUTER_TOO_COSTLY: &str = r#"{"error":{"message":"This request requires more credits, or fewer max_tokens. You requested up to 64000 tokens, but can only afford 1234. To increase, visit https://openrouter.ai/settings/credits and add more credits","code":402}}"#; + let (pubkey, sk) = test_keypair(158); + let key = billing_vkey(&sk, 158); + let mut failures = Vec::new(); + let cases = [ + // (refusing provider, its 402, the next candidate, its mock, whether the 402 cools) + ( + "anthropic", + ANTHROPIC_BILLING, + "openrouter", + Mode::Json, + true, + ), + ( + "openrouter", + OPENROUTER_TOO_COSTLY, + "anthropic", + Mode::AnthropicJson, + false, + ), + ]; + // Replayed by pingora, and past its 64 KiB retry buffer (a `FullBody` re-run). + let large = "x".repeat(100 * 1024); + for ((first, body, next, mode, cools), prompt) in cases + .into_iter() + .flat_map(|c| [(c, "hi"), (c, large.as_str())]) + { + let size = prompt.len(); + let refusing = MockUpstream::start(Mode::Raw(402, "application/json", body)).await; + let serving = MockUpstream::start(mode).await; + let gw = Gateway::builder(unused_nats_port(), &serving.authority(), &b64(&pubkey)) + .providers(&["anthropic", "openrouter"]) + .provider_authority(first, &refusing.authority()) + .provider_authority(next, &serving.authority()) + .start() + .await; + for n in 1..=3 { + let resp = test_client() + .post(format!("{}/v1/chat/completions", gw.url())) + .header("authorization", format!("Bearer {key}")) + .header("content-type", "application/json") + .header("x-beyond-order", format!("{first},{next}")) + .body(format!( + r#"{{"model":"claude-opus-4-8","messages":[{{"role":"user","content":"{prompt}"}}]}}"# + )) + .send() + .await + .unwrap(); + let got = resp.status().as_u16(); + let by = resp + .headers() + .get("x-beyond-provider") + .map(|v| v.to_str().unwrap().to_owned()); + let text = resp.text().await.unwrap(); + if got != 200 || by.as_deref() != Some(next) { + failures.push(format!( + "{first} ({size} B) request {n}: {got} by {by:?}: {text}" + )); + } + } + let cooled = gw + .metric("ai_key_auth_failures_total", r#"reason="unfunded""#) + .await; + let (want_hits, want_cooled) = if cools { (1, 1.0) } else { (3, 0.0) }; + if refusing.hits() != want_hits || serving.hits() != 3 || cooled != want_cooled { + failures.push(format!( + "{first} ({size} B): {} hits on its 402 (want {want_hits}), {} on {next}, {cooled} keys cooled (want {want_cooled})", + refusing.hits(), + serving.hits(), + )); + } + if !failures.is_empty() { + failures.push(gw.log()); + break; + } + } + assert!(failures.is_empty(), "{}", failures.join("\n\n")); +} diff --git a/verify/defects.toml b/verify/defects.toml index fdd1fb25..54772a88 100644 --- a/verify/defects.toml +++ b/verify/defects.toml @@ -2555,3 +2555,17 @@ state = "fixed" test = "an_allowance_snapshot_without_a_cursor_stays_fail_closed" fix = "320db0e" note = "Two fixes. (1) WatchedSet::SEED_FROM_CURSORLESS_SNAPSHOT: deny (fail-open) still seeds from any snapshot; allowance (fail-closed) seeds only from a snapshot with a cursor record, decided before anything is installed. Every writer puts the cursor after the data it covers, so a cursor (even an empty scan's revision 0) means a complete read; only a revision > 0 cursor skips the scan, unchanged. (2) rebuild_snapshot now writes {path}.tmp, fsyncs it, renames over path, fsyncs the directory and reopens path, so a crash leaves the old or the new complete file. Gating on is_resumable instead (as first proposed) would leave an edge gateway with an empty allowance bucket unready with NATS down; e2e on_disk_snapshot_enforces_across_restart_without_nats caught that. Also tested: an_allowance_snapshot_with_a_cursor_seeds_ready, a_deny_snapshot_without_a_cursor_still_blocks_with_nats_down, a_crash_before_the_rename_leaves_the_previous_complete_snapshot, a_rebuild_discards_a_stale_staged_file_and_reopens_the_new_one, only_allowance_refuses_a_cursorless_snapshot." + +[[defect]] +id = "D258" +severity = "med" +area = "Reliability" +title = "A 402 a catalog walk fails over on never cools its key: every later request pays a round trip to the unfunded provider" +impact = "D84 makes a managed walk's 402 a candidate refusal that fails over, and D180 cools an out-of-credit key only from the body (Redact reads it, logging calls Provider::mark_key_bad). A failover abandons the response at its head (pingora's in-place retry and a FullBody re-run alike), so that body is never read and the key never cools: until someone tops up the account, every request on the row first makes a round trip to the unfunded provider (a 402 from OpenRouter, DeepSeek or Anthropic's billing_error) before failing over, a permanent latency and load tax." +confidence = "high" +evidence = "Hermetic: a_402_the_walk_fails_over_on_cools_an_unfunded_key. With x-beyond-order anthropic,openrouter on claude-opus-4-8, an Anthropic mock answering a billing_error 402 was sent all three requests (each failed over to OpenRouter and served 200), ai_key_auth_failures_total{reason=\"unfunded\"} read 0; the same with a 100 KiB body (the FullBody re-run). Found by the mutation-testing triage of proxy.rs." +claims = ["REL-4"] +state = "fixed" +test = "a_402_the_walk_fails_over_on_cools_an_unfunded_key" +fix = "3bd64c4" +note = "Reading the refused 402's body before abandoning it, as first proposed, is not possible: pingora 0.9's upstream_response_filter gets the head only, the upstream session is not reachable from any hook, and an Err there drops the connection with the body unread (the same reason D180 could not fail over the request that saw the answer). So the status decides, where it can: remedy::unfunded_402 says a 402 is out of credit by its status alone on every provider but OpenRouter, whose 402 may be one request larger than the balance (\"This request requires more credits\", which must not cool the shared key: D180, D200). upstream_response_filter cools the key (AiProxy::cool_unfunded_key: same metric reason, same warn line as logging's D180 path) on both abandoning paths, the in-place retry and a recorded FullBody retry; a FullBody final attempt is relayed and cooled from its body as before. No new state (Provider::mark_key_bad, the existing key cooldown) and no work on any other status, the 2xx path included. logging no longer cools from the body of an abandoned FullBody attempt (relay_abandoned), which raced the parent's drop and would count a head-cooled 402 twice; this also makes a FullBody key walk's abandoned bodies deterministically unread, as ARCHITECTURE.md already said. Limit: an OpenRouter 402 the walk fails over on still cools nothing, so a row that leads with OpenRouter (or an x-beyond-order that puts it first) keeps a round trip to an unfunded OpenRouter account; by default the aggregator is last in the walk (D253), where its 402 is relayed and cooled from the body. Also tested: remedy::tests::only_openrouter_needs_the_body_of_a_402; the same test asserts the OpenRouter too-costly 402 fails over and cools nothing (OpenRouter is sent all three requests) for both body sizes."