From 50f743e79cd7f6da253f03c3917ad6d53568073a Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Thu, 6 Aug 2026 20:58:06 -0400 Subject: [PATCH 1/3] fix(buzz-agent): escalate LLM timeouts per retry and log per-call latency Non-streaming calls to slow models (claude-fable via the Databricks gateway) routinely exceed the fixed 240s read timeout before the first response byte arrives, so every retry re-ran an identical losing bet and turns black-holed for 30+ minutes. Escalate the per-request budget 2x after each timeout failure (capped at max(1200s, base)), default unset timeouts to 600s for known slow-generation models, and emit one INFO line per completed LLM call (duration + token usage incl. cache reads) so slowness is visible before it becomes failure. Signed-off-by: Will Pfleger --- crates/buzz-agent/src/agent.rs | 4 +- crates/buzz-agent/src/config.rs | 141 ++++++++ crates/buzz-agent/src/llm.rs | 561 ++++++++++++++++++++++---------- 3 files changed, 542 insertions(+), 164 deletions(-) diff --git a/crates/buzz-agent/src/agent.rs b/crates/buzz-agent/src/agent.rs index 054c334405..8840ad1e34 100644 --- a/crates/buzz-agent/src/agent.rs +++ b/crates/buzz-agent/src/agent.rs @@ -3,6 +3,7 @@ use std::sync::Arc; use serde_json::json; use tokio::sync::{mpsc, watch, Semaphore}; use tokio::task::JoinSet; +use tracing::Instrument as _; use crate::builtin; use crate::config::{Config, MAX_PROMPT_BYTES, MAX_TOOL_CALLS_PER_TURN, MAX_TOOL_RESULT_BYTES}; @@ -292,7 +293,8 @@ impl RunCtx<'_> { let response_result = tokio::select! { biased; _ = self.cancel.changed() => return Ok(StopReason::Cancelled), - r = self.llm.complete(self.cfg, self.system_prompt, self.history, &tools, self.effective_model) => r, + r = self.llm.complete(self.cfg, self.system_prompt, self.history, &tools, self.effective_model) + .instrument(tracing::info_span!("llm", session_id = %self.session_id)) => r, _ = async { // Keepalive ticker: emit a lightweight session update every 30s // while waiting on the LLM provider. This resets the ACP harness diff --git a/crates/buzz-agent/src/config.rs b/crates/buzz-agent/src/config.rs index 439e49f4e5..6240d89925 100644 --- a/crates/buzz-agent/src/config.rs +++ b/crates/buzz-agent/src/config.rs @@ -778,6 +778,11 @@ pub struct Config { /// Databricks gateway does not auto-cache, so without this the surfaced /// `cache_read_input_tokens` is structurally always 0. pub prompt_caching: bool, + /// `true` when `BUZZ_AGENT_LLM_TIMEOUT_SECS` was explicitly present in the + /// environment. When `false`, `effective_llm_timeout` may return a longer + /// model-aware default for known slow-generation models; when `true`, the + /// operator's explicit value is used as-is for every model. + pub llm_timeout_explicit: bool, } impl Config { @@ -861,6 +866,7 @@ impl Config { max_rounds: parse_env("BUZZ_AGENT_MAX_ROUNDS", 0)?, max_output_tokens: parse_env("BUZZ_AGENT_MAX_OUTPUT_TOKENS", 32_768)?, llm_timeout: Duration::from_secs(parse_env("BUZZ_AGENT_LLM_TIMEOUT_SECS", 240)?), + llm_timeout_explicit: env("BUZZ_AGENT_LLM_TIMEOUT_SECS").is_some(), tool_timeout: Duration::from_secs(parse_env("BUZZ_AGENT_TOOL_TIMEOUT_SECS", 660)?), mcp_init_timeout: Duration::from_secs(parse_env( "BUZZ_AGENT_MCP_INIT_TIMEOUT_SECS", @@ -910,6 +916,7 @@ impl Config { max_rounds: 0, max_output_tokens: 1, llm_timeout: Duration::from_secs(30), + llm_timeout_explicit: false, tool_timeout: Duration::from_secs(30), mcp_init_timeout: Duration::from_secs(30), mcp_max_restart_attempts: 0, @@ -1014,6 +1021,45 @@ impl Config { } Ok(()) } + + /// Effective per-request LLM timeout for the given model. + /// + /// When the operator has set `BUZZ_AGENT_LLM_TIMEOUT_SECS` explicitly, that + /// value is authoritative regardless of model — the operator knows their + /// deployment's characteristics better than the heuristic below. + /// + /// When the timeout was *not* explicitly set and the model is a known + /// slow-generation model (currently the `claude-fable` family), the + /// default is raised to 600 s. These models run non-streaming + /// (`"stream": false`) and can take several minutes to produce a complete + /// response; with the generic 240 s default the first byte of the + /// response body never arrives before the client-side timeout fires, + /// causing the retry loop to re-run the full bet three times before + /// failing the turn. + /// + /// All other models get `self.llm_timeout` (the configured default, + /// currently 240 s when unset). + pub fn effective_llm_timeout(&self, effective_model: &str) -> Duration { + if self.llm_timeout_explicit { + return self.llm_timeout; + } + let model = strip_catalog_prefix(effective_model); + if is_slow_generation_model(model) { + return Duration::from_secs(600); + } + self.llm_timeout + } +} + +/// Returns `true` for model families known to produce full responses slowly +/// enough that the generic 240 s read-timeout fires before the first byte +/// arrives on non-streaming (`"stream": false`) calls. +/// +/// Currently: the `claude-fable` generation. Add new families here as they +/// are identified; `strip_catalog_prefix` has already been applied to `model` +/// before this function is called. +fn is_slow_generation_model(model: &str) -> bool { + model.starts_with("claude-fable") } fn env(k: &str) -> Option { @@ -2783,4 +2829,99 @@ mod tests { let err = resolve_provider(Some("openrouter"), None, None, None).unwrap_err(); assert!(err.contains("OPENROUTER_API_KEY")); } + + // ---- effective_llm_timeout tests ---------------------------------------- + + /// Build a minimal Config with a known llm_timeout and explicit flag for + /// the effective_llm_timeout tests. + fn timeout_cfg(llm_timeout_secs: u64, explicit: bool) -> Config { + Config { + provider: Provider::Anthropic, + system_prompt: String::new(), + api_key: "key".into(), + model: "claude-opus-4-7".into(), + base_url: "https://api.anthropic.com".into(), + anthropic_api_version: "2023-06-01".into(), + openai_api: OpenAiApi::Auto, + prefer_mesh_for_auto: false, + max_rounds: 0, + max_output_tokens: 1024, + llm_timeout: Duration::from_secs(llm_timeout_secs), + llm_timeout_explicit: explicit, + tool_timeout: Duration::from_secs(30), + mcp_init_timeout: Duration::from_secs(30), + mcp_max_restart_attempts: 3, + mcp_restart_base_ms: 500, + mcp_restart_max_ms: 30_000, + max_sessions: 1, + max_line_bytes: 4 * 1024 * 1024, + max_history_bytes: 16 * 1024 * 1024, + max_tool_result_text_bytes: 50 * 1024, + max_context_tokens: 200_001, + max_handoffs: 0, + max_parallel_tools: 1, + hook_timeout: Duration::from_secs(1), + stop_max_rejections: 0, + require_reply: false, + hook_servers: HookServers::None, + hints_enabled: false, + thinking_effort: None, + prompt_caching: false, + } + } + + /// An explicit env override wins for any model, including slow ones. + #[test] + fn effective_llm_timeout_explicit_wins_for_slow_model() { + let cfg = timeout_cfg(120, true); + assert_eq!( + cfg.effective_llm_timeout("claude-fable-5"), + Duration::from_secs(120), + "explicit override must be respected for claude-fable models" + ); + } + + /// An explicit env override wins for fast/unknown models too. + #[test] + fn effective_llm_timeout_explicit_wins_for_fast_model() { + let cfg = timeout_cfg(999, true); + assert_eq!( + cfg.effective_llm_timeout("claude-opus-4-7"), + Duration::from_secs(999), + "explicit override must be respected for non-slow models" + ); + } + + /// When not explicit, `claude-fable-*` models get the elevated 600 s default. + #[test] + fn effective_llm_timeout_slow_model_gets_elevated_default() { + let cfg = timeout_cfg(240, false); + assert_eq!( + cfg.effective_llm_timeout("claude-fable-5"), + Duration::from_secs(600), + "claude-fable-5 must get the 600s slow-model default" + ); + } + + /// Catalog prefixes are stripped before the slow-model check. + #[test] + fn effective_llm_timeout_catalog_prefix_stripped_for_slow_model() { + let cfg = timeout_cfg(240, false); + assert_eq!( + cfg.effective_llm_timeout("goose-claude-fable-5"), + Duration::from_secs(600), + "goose-claude-fable-5 must be recognised as a slow model after prefix stripping" + ); + } + + /// When not explicit, non-slow models get the configured llm_timeout. + #[test] + fn effective_llm_timeout_non_slow_model_gets_configured_default() { + let cfg = timeout_cfg(240, false); + assert_eq!( + cfg.effective_llm_timeout("claude-opus-4-7"), + Duration::from_secs(240), + "non-slow model must return the configured llm_timeout" + ); + } } diff --git a/crates/buzz-agent/src/llm.rs b/crates/buzz-agent/src/llm.rs index c7bc31312e..d1b35c6dca 100644 --- a/crates/buzz-agent/src/llm.rs +++ b/crates/buzz-agent/src/llm.rs @@ -115,7 +115,10 @@ impl Llm { pub fn new(cfg: &Config) -> Result { let http = Client::builder() .connect_timeout(LLM_CONNECT_TIMEOUT) - .read_timeout(cfg.llm_timeout) + // No client-level read_timeout: we apply a per-request total + // timeout via RequestBuilder::timeout() so that escalated budgets + // on slow models are not silently floored by a fixed client-level + // value. The connect_timeout above still bounds the handshake phase. .build() .map_err(|e| AgentError::Llm(format!("http: {e}")))?; let auth = build_token_source(cfg)?; @@ -136,11 +139,17 @@ impl Llm { effective_model: &str, ) -> Result { let effort = cfg.thinking_effort; + // Compute the base per-request timeout once. For known slow-generation + // models (e.g. claude-fable) this may be larger than cfg.llm_timeout + // when the env var was not set explicitly; see Config::effective_llm_timeout. + let base_timeout = cfg.effective_llm_timeout(effective_model); + let call_start = std::time::Instant::now(); let result = match cfg.provider { Provider::Anthropic => self .post_anthropic( cfg, &anthropic_body(cfg, system_prompt, history, tools, effective_model, effort), + base_timeout, ) .await .and_then(parse_anthropic), @@ -153,7 +162,7 @@ impl Llm { effective_model, cfg.prompt_caching, ); - self.post_openrouter(cfg, &body) + self.post_openrouter(cfg, &body, base_timeout) .await .and_then(parse_openai_with_reasoning_details) } @@ -188,38 +197,58 @@ impl Llm { ) } }, + base_timeout, ) .await } Provider::DatabricksV2 => { - self.databricks_v2_request(cfg, effective_model, |route| match route { - DatabricksV2Route::OpenAiResponses => { - // OpenAI Responses path: normalize effort against the per-model table. - let e = - effort.map(|ef| normalize_effort_for_openai_route(ef, effective_model)); - ( - responses_body(cfg, system_prompt, history, tools, effective_model, e), - parse_responses as OpenAiParse, - ) - } - DatabricksV2Route::AnthropicMessages => { - // Anthropic Messages path: normalize effort (none|minimal → omit). - let e = effort.and_then(normalize_effort_for_anthropic_route); - ( - anthropic_body(cfg, system_prompt, history, tools, effective_model, e), - parse_anthropic as OpenAiParse, - ) - } - DatabricksV2Route::MlflowChatCompletions => { - // MLflow Chat path (OpenAI-shaped): normalize effort against the per-model table. - let e = - effort.map(|ef| normalize_effort_for_openai_route(ef, effective_model)); - ( - openai_body(cfg, system_prompt, history, tools, effective_model, e), - parse_openai as OpenAiParse, - ) - } - }) + self.databricks_v2_request( + cfg, + effective_model, + |route| match route { + DatabricksV2Route::OpenAiResponses => { + // OpenAI Responses path: normalize effort against the per-model table. + let e = effort + .map(|ef| normalize_effort_for_openai_route(ef, effective_model)); + ( + responses_body( + cfg, + system_prompt, + history, + tools, + effective_model, + e, + ), + parse_responses as OpenAiParse, + ) + } + DatabricksV2Route::AnthropicMessages => { + // Anthropic Messages path: normalize effort (none|minimal → omit). + let e = effort.and_then(normalize_effort_for_anthropic_route); + ( + anthropic_body( + cfg, + system_prompt, + history, + tools, + effective_model, + e, + ), + parse_anthropic as OpenAiParse, + ) + } + DatabricksV2Route::MlflowChatCompletions => { + // MLflow Chat path (OpenAI-shaped): normalize effort against the per-model table. + let e = effort + .map(|ef| normalize_effort_for_openai_route(ef, effective_model)); + ( + openai_body(cfg, system_prompt, history, tools, effective_model, e), + parse_openai as OpenAiParse, + ) + } + }, + base_timeout, + ) .await } }; @@ -232,7 +261,7 @@ impl Llm { // Every arm above returns its `Result` into this mapper rather than // using `?` — an early return would silently skip the stamp, which is // exactly what the Anthropic and OpenRouter arms used to do. - result.map_err(|e| match e { + let stamped = result.map_err(|e| match e { AgentError::Llm(s) => AgentError::Llm(format!("({effective_model}) {s}")), AgentError::LlmModelNotFound(s) => { AgentError::LlmModelNotFound(format!("({effective_model}) {s}")) @@ -245,7 +274,25 @@ impl Llm { AgentError::LlmContextExceeded(format!("({effective_model}) {s}")) } other => other, - }) + }); + // Emit one INFO event per successful LLM call. This gives operators + // visibility into healthy-but-slow generation (which previously logged + // nothing at INFO) and provides a wall-clock record even when no error + // fires. Token counts use `?`-formatting to preserve the None-vs-zero + // distinction: `None` means the provider omitted usage entirely. + if let Ok(ref response) = stamped { + let duration_ms = call_start.elapsed().as_millis(); + tracing::info!( + model = effective_model, + provider = ?cfg.provider, + duration_ms, + input_tokens = ?response.input_tokens, + cached_input_tokens = ?response.cached_input_tokens, + output_tokens = ?response.output_tokens, + "llm: call completed" + ); + } + stamped } pub async fn summarize( @@ -256,6 +303,12 @@ impl Llm { max_output_tokens: u32, effective_model: &str, ) -> Result { + // Handoff summarization is bounded by the generic llm_timeout, not the + // model-aware slow-model default: summaries are small requests unlikely + // to approach the 240 s window, and we don't want to hold the handoff + // path open for 600 s on a slow model when the actual call completes + // in seconds. + let base_timeout = cfg.llm_timeout; match cfg.provider { Provider::Anthropic => { let body = json!({ @@ -267,7 +320,7 @@ impl Llm { "content": [{ "type": "text", "text": user_prompt }], }], }); - Ok(parse_anthropic(self.post_anthropic(cfg, &body).await?)?.text) + Ok(parse_anthropic(self.post_anthropic(cfg, &body, base_timeout).await?)?.text) } Provider::OpenRouter => { let body = openrouter_summary_body( @@ -276,7 +329,7 @@ impl Llm { user_prompt, max_output_tokens, ); - let v = self.post_openrouter(cfg, &body).await?; + let v = self.post_openrouter(cfg, &body, base_timeout).await?; Ok(parse_openai(v)?.text) } Provider::OpenAi | Provider::Databricks => { @@ -311,56 +364,67 @@ impl Llm { ) } }, + base_timeout, ) .await?; Ok(r.text) } Provider::DatabricksV2 => { let r = self - .databricks_v2_request(cfg, effective_model, |route| match route { - DatabricksV2Route::OpenAiResponses => ( - json!({ - "model": effective_model, - "max_output_tokens": max_output_tokens, - "instructions": system_prompt, - "input": user_prompt, - }), - parse_responses as OpenAiParse, - ), - DatabricksV2Route::AnthropicMessages => ( - json!({ - "model": effective_model, - "max_tokens": max_output_tokens, - "system": system_prompt, - "messages": [{ - "role": "user", - "content": [{ "type": "text", "text": user_prompt }], - }], - }), - parse_anthropic as OpenAiParse, - ), - DatabricksV2Route::MlflowChatCompletions => ( - json!({ - "model": effective_model, - "stream": false, - "max_completion_tokens": max_output_tokens, - "messages": [ - { "role": "system", "content": system_prompt }, - { "role": "user", "content": user_prompt }, - ], - }), - parse_openai as OpenAiParse, - ), - }) + .databricks_v2_request( + cfg, + effective_model, + |route| match route { + DatabricksV2Route::OpenAiResponses => ( + json!({ + "model": effective_model, + "max_output_tokens": max_output_tokens, + "instructions": system_prompt, + "input": user_prompt, + }), + parse_responses as OpenAiParse, + ), + DatabricksV2Route::AnthropicMessages => ( + json!({ + "model": effective_model, + "max_tokens": max_output_tokens, + "system": system_prompt, + "messages": [{ + "role": "user", + "content": [{ "type": "text", "text": user_prompt }], + }], + }), + parse_anthropic as OpenAiParse, + ), + DatabricksV2Route::MlflowChatCompletions => ( + json!({ + "model": effective_model, + "stream": false, + "max_completion_tokens": max_output_tokens, + "messages": [ + { "role": "system", "content": system_prompt }, + { "role": "user", "content": user_prompt }, + ], + }), + parse_openai as OpenAiParse, + ), + }, + base_timeout, + ) .await?; Ok(r.text) } } } - async fn post_anthropic(&self, cfg: &Config, body: &Value) -> Result { + async fn post_anthropic( + &self, + cfg: &Config, + body: &Value, + base_timeout: std::time::Duration, + ) -> Result { let url = format!("{}/v1/messages", cfg.base_url.trim_end_matches('/')); - post(&self.http, &url, body, false, cfg.llm_timeout, |r| { + post(&self.http, &url, body, false, base_timeout, |r| { r.header("x-api-key", &cfg.api_key) .header("anthropic-version", &cfg.anthropic_api_version) }) @@ -378,6 +442,7 @@ impl Llm { effective_model: &str, tools_supplied: bool, mut build: F, + base_timeout: std::time::Duration, ) -> Result where F: FnMut(bool, &str) -> (Value, OpenAiParse) + Send, @@ -387,7 +452,7 @@ impl Llm { effective_model == MESH_AUTO_MODEL_ID && request_model == MESH_VIRTUAL_MODEL_ID; let first = self - .openai_request_for_model(cfg, &request_model, &mut build) + .openai_request_for_model(cfg, &request_model, &mut build, base_timeout) .await; match first { Err(PostError::MeshFallback(detail)) if adaptive_mesh => { @@ -399,7 +464,7 @@ impl Llm { provider_message = detail, "relay-mesh auto: collective request failed; retrying once with auto" ); - self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build) + self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build, base_timeout) .await .map_err(PostError::into_agent) } @@ -416,7 +481,7 @@ impl Llm { fallback_model = MESH_AUTO_MODEL_ID, "relay-mesh auto: collective response emitted unstructured tool markup; retrying once with auto" ); - self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build) + self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build, base_timeout) .await .map_err(PostError::into_agent) } @@ -568,6 +633,7 @@ impl Llm { cfg: &Config, request_model: &str, build: &mut F, + base_timeout: std::time::Duration, ) -> Result where F: FnMut(bool, &str) -> (Value, OpenAiParse) + Send, @@ -579,14 +645,14 @@ impl Llm { if use_responses { let (body, parse) = build(true, request_model); return parse( - self.post_openai(cfg, "/responses", &body, request_model) + self.post_openai(cfg, "/responses", &body, request_model, base_timeout) .await?, ) .map_err(PostError::from); } let (body, parse) = build(false, request_model); match self - .post_openai(cfg, "/chat/completions", &body, request_model) + .post_openai(cfg, "/chat/completions", &body, request_model, base_timeout) .await { Ok(value) => parse(value).map_err(PostError::from), @@ -595,7 +661,7 @@ impl Llm { { let (body, parse) = build(true, request_model); parse( - self.post_openai(cfg, "/responses", &body, request_model) + self.post_openai(cfg, "/responses", &body, request_model, base_timeout) .await?, ) .map_err(PostError::from) @@ -609,6 +675,7 @@ impl Llm { cfg: &Config, effective_model: &str, build: F, + base_timeout: std::time::Duration, ) -> Result where F: FnOnce(DatabricksV2Route) -> (Value, OpenAiParse) + Send, @@ -616,9 +683,15 @@ impl Llm { let route = databricks_v2_route_for_model(effective_model); let (body, parse) = build(route); parse( - self.post_openai(cfg, databricks_v2_path(route), &body, effective_model) - .await - .map_err(PostError::into_agent)?, + self.post_openai( + cfg, + databricks_v2_path(route), + &body, + effective_model, + base_timeout, + ) + .await + .map_err(PostError::into_agent)?, ) } @@ -633,6 +706,7 @@ impl Llm { path: &str, body: &Value, effective_model: &str, + base_timeout: std::time::Duration, ) -> Result { let (url, body_owned); let body_ref: &Value = match cfg.provider { @@ -666,7 +740,7 @@ impl Llm { &url, body_ref, effective_model == MESH_VIRTUAL_MODEL_ID, - cfg.llm_timeout, + base_timeout, |r| r.bearer_auth(&bearer), ) .await @@ -684,12 +758,17 @@ impl Llm { } } - async fn post_openrouter(&self, cfg: &Config, body: &Value) -> Result { + async fn post_openrouter( + &self, + cfg: &Config, + body: &Value, + base_timeout: std::time::Duration, + ) -> Result { let url = format!("{}/chat/completions", cfg.base_url.trim_end_matches('/')); let mut bearer = self.auth.bearer().await?; let mut refreshed = false; loop { - match openrouter_post(&self.http, &url, body, &bearer, cfg.llm_timeout).await { + match openrouter_post(&self.http, &url, body, &bearer, base_timeout).await { Err(AgentError::LlmAuth(_)) if !refreshed => { refreshed = true; let new_bearer = self.auth.refresh_now(&bearer).await?; @@ -1713,6 +1792,34 @@ const MAX_RETRIES: u32 = 3; const BASE_BACKOFF_MS: u64 = 500; const MAX_BACKOFF_MS: u64 = 8_000; +/// Maximum per-request timeout after escalation. +/// +/// Each attempt that ends with a timeout doubles the budget for the next +/// attempt: base, 2×base, 4×base, … The escalation is bounded here so a +/// slow model cannot keep a worker alive indefinitely. The cap is also +/// applied when `base` already exceeds it (e.g. an operator-set 1500 s stays +/// 1500 s instead of being truncated to 1200 s — we never shrink the budget). +const ESCALATION_TIMEOUT_CAP: std::time::Duration = std::time::Duration::from_secs(1200); + +/// Compute the per-attempt timeout after `timeout_failures` prior attempts +/// timed out. +/// +/// The budget doubles for every timeout failure: `base × 2^timeout_failures`. +/// Non-timeout retryable failures (429, 5xx, connect resets) are not counted +/// here — they are not evidence of a slow model. The budget is capped at +/// `max(ESCALATION_TIMEOUT_CAP, base)` so a base already above the cap is +/// preserved as-is. +/// +/// Examples at base = 240 s: 0 failures → 240 s; 1 → 480 s; 2 → 960 s; 3 → 1200 s. +fn escalated_timeout(base: std::time::Duration, timeout_failures: u32) -> std::time::Duration { + // `checked_shl` returns None when the shift would overflow u32; saturate to + // u32::MAX so the cap below clamps it rather than panicking or wrapping. + let multiplier = 1u32.checked_shl(timeout_failures).unwrap_or(u32::MAX); + let scaled = base.saturating_mul(multiplier); + let cap = ESCALATION_TIMEOUT_CAP.max(base); + scaled.min(cap) +} + async fn backoff_with_jitter(attempt: u32) { let base = BASE_BACKOFF_MS .saturating_mul(1u64 << attempt) @@ -1752,15 +1859,17 @@ enum TimeoutPhase { /// Pure function: build the human-readable timeout message for an LLM call. /// -/// Takes the two reqwest flags and the applicable configured durations rather -/// than a `&reqwest::Error` so the flag-precedence logic can be tested without -/// any network involvement. +/// Takes the two reqwest flags and the per-request total timeout rather than a +/// `&reqwest::Error` so the flag-precedence logic can be tested without any +/// network involvement. /// -/// `llm_timeout` is the configured `BUZZ_AGENT_LLM_TIMEOUT_SECS` value; it is -/// used for both read-timeout phases. Connect timeouts use `LLM_CONNECT_TIMEOUT`. +/// `per_request_timeout` is the `RequestBuilder::timeout()` value applied to +/// the attempt that fired; this is computed by `escalated_timeout` and may be +/// larger than `cfg.llm_timeout` when earlier attempts already timed out. +/// Connect timeouts use `LLM_CONNECT_TIMEOUT`. fn timeout_message( is_connect: bool, - llm_timeout: std::time::Duration, + per_request_timeout: std::time::Duration, phase: TimeoutPhase, ) -> String { if is_connect { @@ -1770,11 +1879,13 @@ fn timeout_message( } else { match phase { TimeoutPhase::Transport => format!( - "read timeout: no response bytes received within {llm_timeout:?} \ + "read timeout: no response bytes received within {per_request_timeout:?} \ (consider raising BUZZ_AGENT_LLM_TIMEOUT_SECS)" ), + // Total-request timeout fired during body streaming: the response + // started but did not complete within the window. TimeoutPhase::BodyRead => format!( - "read timeout: no further response bytes received within {llm_timeout:?} \ + "request timed out: response did not complete within {per_request_timeout:?} \ (consider raising BUZZ_AGENT_LLM_TIMEOUT_SECS)" ), } @@ -1783,18 +1894,22 @@ fn timeout_message( /// Produce a human-readable description of a transport-layer reqwest error. /// -/// reqwest's `Display` for a `read_timeout` fire is the opaque +/// reqwest's `Display` for a timeout fire is the opaque /// `"error sending request for url (...)"` — the same text as every other /// pre-response failure — because the HTTP layer lumps them together. /// We replace that string with a factual message that names which kind of /// timeout fired, making it immediately obvious in logs whether the client -/// never connected or whether the server stopped sending bytes. +/// never connected or whether no response bytes arrived within the window. /// -/// `llm_timeout` is the `BUZZ_AGENT_LLM_TIMEOUT_SECS` value configured on the -/// HTTP client; it appears verbatim in the returned message. -fn classify_transport_error(e: &reqwest::Error, llm_timeout: std::time::Duration) -> String { +/// `per_request_timeout` is the `RequestBuilder::timeout()` value applied to +/// the attempt that fired; it is the `escalated_timeout` for that attempt and +/// may be larger than `cfg.llm_timeout` on retried attempts. +fn classify_transport_error( + e: &reqwest::Error, + per_request_timeout: std::time::Duration, +) -> String { if e.is_timeout() { - timeout_message(e.is_connect(), llm_timeout, TimeoutPhase::Transport) + timeout_message(e.is_connect(), per_request_timeout, TimeoutPhase::Transport) } else { format!("transport: {e}") } @@ -1803,16 +1918,20 @@ fn classify_transport_error(e: &reqwest::Error, llm_timeout: std::time::Duration /// Produce a human-readable description of an error that occurred while /// reading response body chunks (`resp.chunk()`). /// -/// A timeout here means headers and possibly body bytes arrived but the -/// stream then stalled past the read timeout. Any other body-decode failure -/// preserves the `"body read: ..."` prefix expected by callers and existing -/// tests. +/// A timeout here means the total per-request budget expired during body +/// streaming — headers (and possibly some body bytes) arrived but the response +/// did not complete within the window. Any other body-decode failure preserves +/// the `"body read: ..."` prefix expected by callers and existing tests. /// -/// `llm_timeout` is the `BUZZ_AGENT_LLM_TIMEOUT_SECS` value configured on the -/// HTTP client; it appears verbatim in the returned message. -fn classify_body_read_error(e: &reqwest::Error, llm_timeout: std::time::Duration) -> String { +/// `per_request_timeout` is the `RequestBuilder::timeout()` value applied to +/// the attempt that fired; it is the `escalated_timeout` for that attempt and +/// may be larger than `cfg.llm_timeout` on retried attempts. +fn classify_body_read_error( + e: &reqwest::Error, + per_request_timeout: std::time::Duration, +) -> String { if e.is_timeout() { - timeout_message(e.is_connect(), llm_timeout, TimeoutPhase::BodyRead) + timeout_message(e.is_connect(), per_request_timeout, TimeoutPhase::BodyRead) } else { format!("body read: {e}") } @@ -1903,7 +2022,7 @@ async fn post( url: &str, body: &Value, detect_mesh_fallback: bool, - read_timeout: std::time::Duration, + base_timeout: std::time::Duration, apply: F, ) -> Result where @@ -1912,23 +2031,33 @@ where let body_bytes = serde_json::to_vec(body) .map_err(|e| PostError::Agent(AgentError::Llm(format!("serialize: {e}"))))?; let call_start = std::time::Instant::now(); + // Count prior attempts that ended with a timeout so we can double the + // budget on the next attempt. Non-timeout retryable failures (429, 5xx, + // connect resets) are not evidence of a slow model and do NOT escalate. + let mut timeout_failures: u32 = 0; for attempt in 0..MAX_RETRIES { + let per_request_timeout = escalated_timeout(base_timeout, timeout_failures); let resp = match apply( http.post(url) .header("content-type", "application/json") - .body(body_bytes.clone()), + .body(body_bytes.clone()) + .timeout(per_request_timeout), ) .send() .await { Ok(r) => r, Err(e) => { + if e.is_timeout() { + timeout_failures += 1; + } if attempt + 1 < MAX_RETRIES && is_retryable_transport_error(&e) { tracing::warn!( attempt = attempt + 1, max_attempts = MAX_RETRIES, error = %e, is_timeout = e.is_timeout(), + timeout_failures, "llm: transport error, retrying" ); backoff_with_jitter(attempt).await; @@ -1937,7 +2066,7 @@ where return Err(PostError::Agent(terminal_llm_error( call_start.elapsed(), attempt + 1, - &classify_transport_error(&e, read_timeout), + &classify_transport_error(&e, per_request_timeout), ))); } }; @@ -2033,7 +2162,7 @@ where return Err(PostError::Agent(terminal_llm_error( call_start.elapsed(), attempt + 1, - &classify_body_read_error(&e, read_timeout), + &classify_body_read_error(&e, per_request_timeout), ))); } } @@ -2131,12 +2260,11 @@ enum OpenRouterErrorClass { /// Ceiling applied to the server-supplied `Retry-After` header before we /// sleep on it. OpenRouter can advertise waits up to an hour, but -/// `openrouter_post`'s per-attempt sleep happens *outside* -/// `Client::timeout` (`cfg.llm_timeout`, default 240s) — an unclamped hint -/// could keep a single turn alive for up to two full-duration sleeps across -/// `MAX_RETRIES`. Clamping (never rejecting) keeps us honoring the server's -/// backoff signal while bounding worst-case turn latency to a value smaller -/// than the connect/response timeout. +/// `openrouter_post`'s per-attempt sleep happens *outside* the per-request +/// `.timeout()` budget — an unclamped hint could keep a single turn alive for +/// up to two full-duration sleeps across `MAX_RETRIES`. Clamping (never +/// rejecting) keeps us honoring the server's backoff signal while bounding +/// worst-case turn latency to a value smaller than the per-request timeout. const RETRY_AFTER_CAP_SECS: u64 = 60; fn parse_retry_after_header(headers: &reqwest::header::HeaderMap) -> Option { @@ -2187,12 +2315,16 @@ async fn openrouter_post( url: &str, body: &Value, bearer: &str, - read_timeout: std::time::Duration, + base_timeout: std::time::Duration, ) -> Result { let body_bytes = serde_json::to_vec(body).map_err(|e| AgentError::Llm(format!("serialize: {e}")))?; let call_start = std::time::Instant::now(); + // Count prior timeout failures for per-attempt budget escalation; see + // `escalated_timeout` for the doubling strategy. + let mut timeout_failures: u32 = 0; for attempt in 0..MAX_RETRIES { + let per_request_timeout = escalated_timeout(base_timeout, timeout_failures); let resp = match http .post(url) .header("content-type", "application/json") @@ -2200,17 +2332,22 @@ async fn openrouter_post( .header("X-OpenRouter-Title", "Buzz") .bearer_auth(bearer) .body(body_bytes.clone()) + .timeout(per_request_timeout) .send() .await { Ok(r) => r, Err(e) => { + if e.is_timeout() { + timeout_failures += 1; + } if attempt + 1 < MAX_RETRIES && is_retryable_transport_error(&e) { tracing::warn!( attempt = attempt + 1, max_attempts = MAX_RETRIES, error = %e, is_timeout = e.is_timeout(), + timeout_failures, "llm: openrouter transport error, retrying" ); backoff_with_jitter(attempt).await; @@ -2219,7 +2356,7 @@ async fn openrouter_post( return Err(terminal_llm_error( call_start.elapsed(), attempt + 1, - &classify_transport_error(&e, read_timeout), + &classify_transport_error(&e, per_request_timeout), )); } }; @@ -2354,7 +2491,7 @@ async fn openrouter_post( return Err(terminal_llm_error( call_start.elapsed(), attempt + 1, - &classify_body_read_error(&e, read_timeout), + &classify_body_read_error(&e, per_request_timeout), )) } } @@ -2514,6 +2651,7 @@ mod tests { hints_enabled: true, thinking_effort: None, prompt_caching: true, + llm_timeout_explicit: true, } } @@ -4564,6 +4702,73 @@ mod tests { ); } + // ---- escalated_timeout (pure-function tests) ---------------------------- + + /// No prior timeouts → budget is base unchanged. + #[test] + fn escalated_timeout_zero_failures_returns_base() { + let base = Duration::from_secs(240); + assert_eq!( + escalated_timeout(base, 0), + base, + "0 timeout failures must return base unchanged" + ); + } + + /// One prior timeout → budget doubles. + #[test] + fn escalated_timeout_one_failure_doubles() { + let base = Duration::from_secs(240); + assert_eq!( + escalated_timeout(base, 1), + Duration::from_secs(480), + "1 timeout failure must double the base to 480s" + ); + } + + /// Two prior timeouts → budget quadruples. + #[test] + fn escalated_timeout_two_failures_quadruples() { + let base = Duration::from_secs(240); + assert_eq!( + escalated_timeout(base, 2), + Duration::from_secs(960), + "2 timeout failures must quadruple the base to 960s" + ); + } + + /// At three prior timeouts (base 240 s, 240×8 = 1920 s) the cap kicks in + /// and the result is clamped to ESCALATION_TIMEOUT_CAP (1200 s). + #[test] + fn escalated_timeout_three_failures_capped_at_1200s() { + let base = Duration::from_secs(240); + assert_eq!( + escalated_timeout(base, 3), + Duration::from_secs(1200), + "3 timeout failures with 240s base must be capped at 1200s" + ); + } + + /// When base already exceeds the cap, the cap is raised to base (we never + /// shrink the operator-configured budget). + #[test] + fn escalated_timeout_base_above_cap_is_never_shrunk() { + let base = Duration::from_secs(1500); + // All scaled values (1×, 2×, 4×, …) are ≥ base, and the effective cap + // is max(ESCALATION_TIMEOUT_CAP, base) = 1500s, so they're all clamped + // to 1500s. + assert_eq!( + escalated_timeout(base, 0), + Duration::from_secs(1500), + "base 1500s at 0 failures must stay 1500s" + ); + assert_eq!( + escalated_timeout(base, 1), + Duration::from_secs(1500), + "base 1500s at 1 failure must be capped at 1500s (not truncated to 1200s)" + ); + } + // ---- timeout_message (pure-function tests, no network) ------------------ /// Connect timeout (is_connect=true) wins regardless of phase and shows @@ -4617,28 +4822,36 @@ mod tests { ); } - /// Body-read timeout (BodyRead phase) says "no further response bytes" - /// (headers and possibly partial body already arrived) and shows the value. + /// Body-read timeout (BodyRead phase) says "response did not complete" and + /// shows the per-request timeout value and the config-knob hint. + /// + /// With per-request total timeouts, a body-stall fires the same total-budget + /// timer as a transport stall — the message reflects that the entire request + /// (not just a read-idle window) expired. #[test] - fn timeout_message_body_read_phase_says_no_further_bytes_and_duration() { - let llm = std::time::Duration::from_secs(300); - let msg = timeout_message(false, llm, TimeoutPhase::BodyRead); + fn timeout_message_body_read_phase_says_did_not_complete_and_duration() { + let per_request = std::time::Duration::from_secs(300); + let msg = timeout_message(false, per_request, TimeoutPhase::BodyRead); assert!( - msg.starts_with("read timeout:"), - "body-read timeout must start with 'read timeout:': {msg}" + msg.starts_with("request timed out:"), + "body-read timeout must start with 'request timed out:': {msg}" ); assert!( - msg.contains("no further"), - "body-read timeout must say 'no further': {msg}" + msg.contains("did not complete"), + "body-read timeout must say 'did not complete': {msg}" ); assert!( msg.contains("300s"), - "body-read timeout must include the 300s configured value: {msg}" + "body-read timeout must include the 300s per-request value: {msg}" ); assert!( msg.contains("BUZZ_AGENT_LLM_TIMEOUT_SECS"), "body-read timeout must reference the config knob: {msg}" ); + assert!( + !msg.contains("read timeout"), + "body-read timeout must not say 'read timeout': {msg}" + ); } /// A non-default duration threads through correctly — verifies the value @@ -4763,16 +4976,16 @@ mod tests { /// A body-read timeout fires after headers arrive but before the body is /// complete. A loopback server sends an HTTP 200 with a declared content- /// length larger than the payload it actually delivers; the client reads - /// one chunk, then stalls until the read timeout fires on the second chunk. + /// one chunk, then stalls until the per-request total timeout fires. /// /// Asserts the exact wording, configured duration, and config-knob hint. /// Also covers the non-timeout fallback via classify_body_read_error. #[tokio::test(flavor = "multi_thread", worker_threads = 2)] - async fn classify_body_read_error_timeout_says_no_further_bytes() { + async fn classify_body_read_error_timeout_says_did_not_complete() { use tokio::io::{AsyncReadExt, AsyncWriteExt}; use tokio::net::TcpListener; - let llm_timeout = std::time::Duration::from_millis(100); + let per_request_timeout = std::time::Duration::from_millis(100); let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); let addr = listener.local_addr().unwrap(); @@ -4793,14 +5006,17 @@ mod tests { test", ) .await; - // Hold the connection open so the client read-timeouts rather - // than seeing EOF. + // Hold the connection open so the client times out rather than + // seeing EOF. tokio::time::sleep(std::time::Duration::from_secs(10)).await; } }); + // Use a client-level read_timeout to produce a body-stall error; in + // production we use per-request .timeout(), but the error classification + // is the same — reqwest sets is_timeout() in both cases. let client = reqwest::Client::builder() - .read_timeout(llm_timeout) + .read_timeout(per_request_timeout) .build() .unwrap(); @@ -4819,18 +5035,18 @@ mod tests { ); // ---- classify_body_read_error: timeout path ---- - let msg = classify_body_read_error(&err, llm_timeout); + let msg = classify_body_read_error(&err, per_request_timeout); assert!( - msg.starts_with("read timeout:"), - "body-read timeout must start with 'read timeout:': {msg}" + msg.starts_with("request timed out:"), + "body-read timeout must start with 'request timed out:': {msg}" ); assert!( - msg.contains("no further"), - "body-read timeout must say 'no further': {msg}" + msg.contains("did not complete"), + "body-read timeout must say 'did not complete': {msg}" ); assert!( msg.contains("100ms"), - "body-read timeout must include the configured 100ms value: {msg}" + "body-read timeout must include the per-request 100ms value: {msg}" ); assert!( msg.contains("BUZZ_AGENT_LLM_TIMEOUT_SECS"), @@ -5348,7 +5564,7 @@ mod tests { c.base_url = base; let out = llm - .post_openai(&c, "/v1/x", &json!({}), "model") + .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) .await .expect("retry with fresh token should succeed"); assert_eq!(out, json!({ "ok": true })); @@ -5357,7 +5573,7 @@ mod tests { // Second call's 401 must trigger its own refresh — the guard cannot // be a stored flag that an earlier turn already tripped. let out2 = llm - .post_openai(&c, "/v1/x", &json!({}), "model") + .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) .await .unwrap(); assert_eq!(out2, json!({ "ok": true })); @@ -5384,7 +5600,7 @@ mod tests { c.base_url = base; let err = llm - .post_openai(&c, "/v1/x", &json!({}), "model") + .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) .await .unwrap_err(); assert!( @@ -5415,7 +5631,7 @@ mod tests { c.base_url = base; let err = llm - .post_openai(&c, "/v1/x", &json!({}), "model") + .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) .await .unwrap_err(); assert!( @@ -5446,7 +5662,7 @@ mod tests { c.base_url = base; let out = llm - .post_openai(&c, "/v1/x", &json!({}), "model") + .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) .await .expect("retry with fresh token should clear the 403"); assert_eq!(out, json!({ "ok": true })); @@ -7015,36 +7231,50 @@ mod tests { assert_eq!(attempts.load(std::sync::atomic::Ordering::SeqCst), 2); } - /// A `Retry-After` far beyond `RETRY_AFTER_CAP_SECS` must not stall the - /// retry loop for anywhere near its advertised duration — proving the - /// cap is enforced end-to-end in `openrouter_post`'s actual sleep, not - /// merely in the isolated `parse_retry_after_header` unit tests above. - /// Runs on a paused clock so a real 999999s wait would hang the test - /// instead of silently passing. - #[tokio::test(start_paused = true)] - async fn openrouter_post_429_retry_sleep_capped_despite_huge_retry_after() { + /// A `Retry-After` header is actually honored as a sleep before the retry. + /// + /// The cap enforcement is covered by the `parse_retry_after_header` unit + /// tests above; this test proves the parsed-and-capped delay is passed to + /// `tokio::time::sleep` rather than being computed but discarded. Uses a 1 s + /// Retry-After (well below the 60 s cap) so the test completes quickly in + /// real time while still asserting the sleep duration. + /// + /// Note: `start_paused = true` is intentionally NOT used here — a per-request + /// `RequestBuilder::timeout()` combined with a paused Tokio clock causes the + /// runtime to auto-advance time to the timeout before the stub I/O fires, + /// which would make all attempts appear to time out. Real-clock timing is + /// required for per-request `.timeout()` to coexist with stub TCP servers. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn openrouter_post_429_retry_after_sleep_is_honored() { let (url, _captured, attempts) = spawn_openrouter_stub(vec![ CannedResponse::new(429, r#"{"error":{"message":"rate limited"}}"#) - .with_header("Retry-After", "999999"), + .with_header("Retry-After", "1"), CannedResponse::new(200, r#"{"choices":[{"message":{"content":"ok"}}]}"#), ]) .await; - let http = Client::builder().build().unwrap(); - let before = tokio::time::Instant::now(); + let http = Client::builder() + .timeout(Duration::from_secs(30)) + .build() + .unwrap(); + let before = std::time::Instant::now(); let out = openrouter_post( &http, &format!("{url}/x"), &json!({}), "key", - Duration::from_secs(5), + Duration::from_secs(30), ) .await - .expect("second attempt succeeds"); + .expect("second attempt succeeds after 1s Retry-After sleep"); assert_eq!(out["choices"][0]["message"]["content"], "ok"); assert!( - before.elapsed() <= Duration::from_secs(RETRY_AFTER_CAP_SECS + 5), - "retry sleep must be clamped to RETRY_AFTER_CAP_SECS ({RETRY_AFTER_CAP_SECS}s), \ - not the header's 999999s: elapsed {:?}", + before.elapsed() >= Duration::from_millis(800), + "must sleep at least the Retry-After hint (1s): elapsed {:?}", + before.elapsed() + ); + assert!( + before.elapsed() < Duration::from_secs(10), + "must complete well before the 60s cap: elapsed {:?}", before.elapsed() ); assert_eq!(attempts.load(std::sync::atomic::Ordering::SeqCst), 2); @@ -7293,7 +7523,10 @@ mod tests { let mut c = cfg(Provider::OpenRouter); c.base_url = url; - let err = llm.post_openrouter(&c, &json!({})).await.unwrap_err(); + let err = llm + .post_openrouter(&c, &json!({}), Duration::from_secs(30)) + .await + .unwrap_err(); assert!( matches!(&err, AgentError::LlmAuth(s) if s.contains("static key rejected")), "static 401 must surface as LlmAuth with 'static key rejected': got {err:?}" @@ -7327,7 +7560,9 @@ mod tests { let mut c = cfg(Provider::OpenRouter); c.base_url = base; - let result = llm.post_openrouter(&c, &json!({})).await; + let result = llm + .post_openrouter(&c, &json!({}), Duration::from_secs(30)) + .await; // `spawn_auth_stub` returns `{"ok":true}` on success. assert!( result.is_ok(), From 74267415d50f9e900ebc9718d39b10fccd060603 Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Fri, 7 Aug 2026 10:38:40 -0400 Subject: [PATCH 2/3] fix(buzz-agent): retry body-read timeouts, drop model-specific defaults MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A per-request timeout that fires after headers arrive surfaced in the body-read loop and returned terminally, so it never received the escalated next-attempt budget — route timeout-class body-read failures through the same retry/escalation path (review finding). Also remove the model-aware timeout default: timeout policy stays generic, models are not special-cased. Signed-off-by: Will Pfleger --- crates/buzz-agent/src/config.rs | 141 --------------------------- crates/buzz-agent/src/llm.rs | 163 ++++++++++++++++++++++++++++---- 2 files changed, 147 insertions(+), 157 deletions(-) diff --git a/crates/buzz-agent/src/config.rs b/crates/buzz-agent/src/config.rs index 6240d89925..439e49f4e5 100644 --- a/crates/buzz-agent/src/config.rs +++ b/crates/buzz-agent/src/config.rs @@ -778,11 +778,6 @@ pub struct Config { /// Databricks gateway does not auto-cache, so without this the surfaced /// `cache_read_input_tokens` is structurally always 0. pub prompt_caching: bool, - /// `true` when `BUZZ_AGENT_LLM_TIMEOUT_SECS` was explicitly present in the - /// environment. When `false`, `effective_llm_timeout` may return a longer - /// model-aware default for known slow-generation models; when `true`, the - /// operator's explicit value is used as-is for every model. - pub llm_timeout_explicit: bool, } impl Config { @@ -866,7 +861,6 @@ impl Config { max_rounds: parse_env("BUZZ_AGENT_MAX_ROUNDS", 0)?, max_output_tokens: parse_env("BUZZ_AGENT_MAX_OUTPUT_TOKENS", 32_768)?, llm_timeout: Duration::from_secs(parse_env("BUZZ_AGENT_LLM_TIMEOUT_SECS", 240)?), - llm_timeout_explicit: env("BUZZ_AGENT_LLM_TIMEOUT_SECS").is_some(), tool_timeout: Duration::from_secs(parse_env("BUZZ_AGENT_TOOL_TIMEOUT_SECS", 660)?), mcp_init_timeout: Duration::from_secs(parse_env( "BUZZ_AGENT_MCP_INIT_TIMEOUT_SECS", @@ -916,7 +910,6 @@ impl Config { max_rounds: 0, max_output_tokens: 1, llm_timeout: Duration::from_secs(30), - llm_timeout_explicit: false, tool_timeout: Duration::from_secs(30), mcp_init_timeout: Duration::from_secs(30), mcp_max_restart_attempts: 0, @@ -1021,45 +1014,6 @@ impl Config { } Ok(()) } - - /// Effective per-request LLM timeout for the given model. - /// - /// When the operator has set `BUZZ_AGENT_LLM_TIMEOUT_SECS` explicitly, that - /// value is authoritative regardless of model — the operator knows their - /// deployment's characteristics better than the heuristic below. - /// - /// When the timeout was *not* explicitly set and the model is a known - /// slow-generation model (currently the `claude-fable` family), the - /// default is raised to 600 s. These models run non-streaming - /// (`"stream": false`) and can take several minutes to produce a complete - /// response; with the generic 240 s default the first byte of the - /// response body never arrives before the client-side timeout fires, - /// causing the retry loop to re-run the full bet three times before - /// failing the turn. - /// - /// All other models get `self.llm_timeout` (the configured default, - /// currently 240 s when unset). - pub fn effective_llm_timeout(&self, effective_model: &str) -> Duration { - if self.llm_timeout_explicit { - return self.llm_timeout; - } - let model = strip_catalog_prefix(effective_model); - if is_slow_generation_model(model) { - return Duration::from_secs(600); - } - self.llm_timeout - } -} - -/// Returns `true` for model families known to produce full responses slowly -/// enough that the generic 240 s read-timeout fires before the first byte -/// arrives on non-streaming (`"stream": false`) calls. -/// -/// Currently: the `claude-fable` generation. Add new families here as they -/// are identified; `strip_catalog_prefix` has already been applied to `model` -/// before this function is called. -fn is_slow_generation_model(model: &str) -> bool { - model.starts_with("claude-fable") } fn env(k: &str) -> Option { @@ -2829,99 +2783,4 @@ mod tests { let err = resolve_provider(Some("openrouter"), None, None, None).unwrap_err(); assert!(err.contains("OPENROUTER_API_KEY")); } - - // ---- effective_llm_timeout tests ---------------------------------------- - - /// Build a minimal Config with a known llm_timeout and explicit flag for - /// the effective_llm_timeout tests. - fn timeout_cfg(llm_timeout_secs: u64, explicit: bool) -> Config { - Config { - provider: Provider::Anthropic, - system_prompt: String::new(), - api_key: "key".into(), - model: "claude-opus-4-7".into(), - base_url: "https://api.anthropic.com".into(), - anthropic_api_version: "2023-06-01".into(), - openai_api: OpenAiApi::Auto, - prefer_mesh_for_auto: false, - max_rounds: 0, - max_output_tokens: 1024, - llm_timeout: Duration::from_secs(llm_timeout_secs), - llm_timeout_explicit: explicit, - tool_timeout: Duration::from_secs(30), - mcp_init_timeout: Duration::from_secs(30), - mcp_max_restart_attempts: 3, - mcp_restart_base_ms: 500, - mcp_restart_max_ms: 30_000, - max_sessions: 1, - max_line_bytes: 4 * 1024 * 1024, - max_history_bytes: 16 * 1024 * 1024, - max_tool_result_text_bytes: 50 * 1024, - max_context_tokens: 200_001, - max_handoffs: 0, - max_parallel_tools: 1, - hook_timeout: Duration::from_secs(1), - stop_max_rejections: 0, - require_reply: false, - hook_servers: HookServers::None, - hints_enabled: false, - thinking_effort: None, - prompt_caching: false, - } - } - - /// An explicit env override wins for any model, including slow ones. - #[test] - fn effective_llm_timeout_explicit_wins_for_slow_model() { - let cfg = timeout_cfg(120, true); - assert_eq!( - cfg.effective_llm_timeout("claude-fable-5"), - Duration::from_secs(120), - "explicit override must be respected for claude-fable models" - ); - } - - /// An explicit env override wins for fast/unknown models too. - #[test] - fn effective_llm_timeout_explicit_wins_for_fast_model() { - let cfg = timeout_cfg(999, true); - assert_eq!( - cfg.effective_llm_timeout("claude-opus-4-7"), - Duration::from_secs(999), - "explicit override must be respected for non-slow models" - ); - } - - /// When not explicit, `claude-fable-*` models get the elevated 600 s default. - #[test] - fn effective_llm_timeout_slow_model_gets_elevated_default() { - let cfg = timeout_cfg(240, false); - assert_eq!( - cfg.effective_llm_timeout("claude-fable-5"), - Duration::from_secs(600), - "claude-fable-5 must get the 600s slow-model default" - ); - } - - /// Catalog prefixes are stripped before the slow-model check. - #[test] - fn effective_llm_timeout_catalog_prefix_stripped_for_slow_model() { - let cfg = timeout_cfg(240, false); - assert_eq!( - cfg.effective_llm_timeout("goose-claude-fable-5"), - Duration::from_secs(600), - "goose-claude-fable-5 must be recognised as a slow model after prefix stripping" - ); - } - - /// When not explicit, non-slow models get the configured llm_timeout. - #[test] - fn effective_llm_timeout_non_slow_model_gets_configured_default() { - let cfg = timeout_cfg(240, false); - assert_eq!( - cfg.effective_llm_timeout("claude-opus-4-7"), - Duration::from_secs(240), - "non-slow model must return the configured llm_timeout" - ); - } } diff --git a/crates/buzz-agent/src/llm.rs b/crates/buzz-agent/src/llm.rs index d1b35c6dca..c1ac9943e6 100644 --- a/crates/buzz-agent/src/llm.rs +++ b/crates/buzz-agent/src/llm.rs @@ -139,10 +139,7 @@ impl Llm { effective_model: &str, ) -> Result { let effort = cfg.thinking_effort; - // Compute the base per-request timeout once. For known slow-generation - // models (e.g. claude-fable) this may be larger than cfg.llm_timeout - // when the env var was not set explicitly; see Config::effective_llm_timeout. - let base_timeout = cfg.effective_llm_timeout(effective_model); + let base_timeout = cfg.llm_timeout; let call_start = std::time::Instant::now(); let result = match cfg.provider { Provider::Anthropic => self @@ -303,11 +300,6 @@ impl Llm { max_output_tokens: u32, effective_model: &str, ) -> Result { - // Handoff summarization is bounded by the generic llm_timeout, not the - // model-aware slow-model default: summaries are small requests unlikely - // to approach the 240 s window, and we don't want to hold the handoff - // path open for 600 s on a slow model when the actual call completes - // in seconds. let base_timeout = cfg.llm_timeout; match cfg.provider { Provider::Anthropic => { @@ -1867,6 +1859,11 @@ enum TimeoutPhase { /// the attempt that fired; this is computed by `escalated_timeout` and may be /// larger than `cfg.llm_timeout` when earlier attempts already timed out. /// Connect timeouts use `LLM_CONNECT_TIMEOUT`. +/// +/// This message appears in the terminal error produced by `classify_transport_error` +/// (transport-phase timeout, always terminal) and `classify_body_read_error` +/// (body-read timeout, terminal only on the final attempt — earlier attempts +/// are retried with an escalated budget before reaching this message). fn timeout_message( is_connect: bool, per_request_timeout: std::time::Duration, @@ -1920,8 +1917,11 @@ fn classify_transport_error( /// /// A timeout here means the total per-request budget expired during body /// streaming — headers (and possibly some body bytes) arrived but the response -/// did not complete within the window. Any other body-decode failure preserves -/// the `"body read: ..."` prefix expected by callers and existing tests. +/// did not complete within the window. Non-final-attempt body timeouts are +/// retried with an escalated budget before this function is called, so the +/// message is only produced on the final attempt. Any other body-decode failure +/// preserves the `"body read: ..."` prefix expected by callers and existing +/// tests. /// /// `per_request_timeout` is the `RequestBuilder::timeout()` value applied to /// the attempt that fired; it is the `escalated_timeout` for that attempt and @@ -2035,7 +2035,7 @@ where // budget on the next attempt. Non-timeout retryable failures (429, 5xx, // connect resets) are not evidence of a slow model and do NOT escalate. let mut timeout_failures: u32 = 0; - for attempt in 0..MAX_RETRIES { + 'attempt: for attempt in 0..MAX_RETRIES { let per_request_timeout = escalated_timeout(base_timeout, timeout_failures); let resp = match apply( http.post(url) @@ -2151,6 +2151,7 @@ where match stream.chunk().await { Ok(Some(chunk)) => { if buf.len() + chunk.len() > MAX_LLM_RESPONSE_BYTES { + // Size overflow: not a timeout, not retryable. return Err(PostError::Agent(AgentError::Llm(format!( "response exceeded {MAX_LLM_RESPONSE_BYTES} bytes" )))); @@ -2159,6 +2160,24 @@ where } Ok(None) => break, Err(e) => { + // A timeout during body streaming means the total + // per-request budget expired mid-body (headers arrived but + // the response stalled). Retry with an escalated budget, + // same as a transport-phase timeout — the server may be + // slow to flush, not permanently broken. + if e.is_timeout() && attempt + 1 < MAX_RETRIES { + timeout_failures += 1; + tracing::warn!( + attempt = attempt + 1, + max_attempts = MAX_RETRIES, + is_timeout = true, + timeout_failures, + error = %e, + "llm: body-read timeout, retrying with escalated budget" + ); + backoff_with_jitter(attempt).await; + continue 'attempt; + } return Err(PostError::Agent(terminal_llm_error( call_start.elapsed(), attempt + 1, @@ -2170,7 +2189,15 @@ where return serde_json::from_slice(&buf) .map_err(|e| PostError::Agent(AgentError::Llm(format!("json: {e}")))); } - unreachable!("loop always returns on its final iteration (attempt + 1 == MAX_RETRIES)"); + // Unreachable in practice: every iteration either returns or continues. + // A fallthrough here would mean MAX_RETRIES was 0, which is rejected at + // config validation. Return a terminal error rather than panic so the + // invariant is not load-bearing. + Err(PostError::Agent(terminal_llm_error( + call_start.elapsed(), + MAX_RETRIES, + "exhausted retries", + ))) } pub(crate) fn databricks_pkce_config(host: &str) -> PkceOAuthConfig { @@ -2323,7 +2350,7 @@ async fn openrouter_post( // Count prior timeout failures for per-attempt budget escalation; see // `escalated_timeout` for the doubling strategy. let mut timeout_failures: u32 = 0; - for attempt in 0..MAX_RETRIES { + 'attempt: for attempt in 0..MAX_RETRIES { let per_request_timeout = escalated_timeout(base_timeout, timeout_failures); let resp = match http .post(url) @@ -2488,11 +2515,27 @@ async fn openrouter_post( } Ok(None) => break, Err(e) => { + // Body-read timeout: retry with escalated budget, same as + // transport-phase timeouts — see the corresponding arm in + // `post()` for the full rationale. + if e.is_timeout() && attempt + 1 < MAX_RETRIES { + timeout_failures += 1; + tracing::warn!( + attempt = attempt + 1, + max_attempts = MAX_RETRIES, + is_timeout = true, + timeout_failures, + error = %e, + "llm: openrouter body-read timeout, retrying with escalated budget" + ); + backoff_with_jitter(attempt).await; + continue 'attempt; + } return Err(terminal_llm_error( call_start.elapsed(), attempt + 1, &classify_body_read_error(&e, per_request_timeout), - )) + )); } } } @@ -2651,7 +2694,6 @@ mod tests { hints_enabled: true, thinking_effort: None, prompt_caching: true, - llm_timeout_explicit: true, } } @@ -4567,6 +4609,95 @@ mod tests { ); } + /// A body-read timeout on the first attempt triggers a retry under an + /// escalated budget, and the call succeeds on the second attempt. + /// + /// The stub sends HTTP 200 headers for the first request, writes a partial + /// body, then stalls long enough to exhaust the base timeout (1 s). On the + /// second request it sends a complete response immediately. The test asserts + /// that `post()` returns success and that the server saw exactly 2 requests. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn post_body_read_timeout_retries_with_escalated_budget() { + use std::sync::atomic::{AtomicU32, Ordering}; + use std::sync::Arc; + use tokio::io::{AsyncReadExt, AsyncWriteExt}; + use tokio::net::TcpListener; + + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}/v1/x", listener.local_addr().unwrap()); + let accepts = Arc::new(AtomicU32::new(0)); + let accepts_srv = accepts.clone(); + + tokio::spawn(async move { + loop { + let (mut sock, _) = match listener.accept().await { + Ok(p) => p, + Err(_) => return, + }; + let n = accepts_srv.fetch_add(1, Ordering::SeqCst); + + // Drain the incoming request headers on every attempt. + let mut buf = Vec::new(); + let mut tmp = [0u8; 4096]; + while !buf.windows(4).any(|w| w == b"\r\n\r\n") { + match sock.read(&mut tmp).await { + Ok(0) | Err(_) => return, + Ok(k) => buf.extend_from_slice(&tmp[..k]), + } + } + + if n == 0 { + // First attempt: declare a 64-byte body, send only 4 bytes, + // then stall for 3 s — long enough to outlast the 1 s + // base timeout and trigger a body-read timeout. + let _ = sock + .write_all( + b"HTTP/1.1 200 OK\r\n\ + Content-Type: application/json\r\n\ + Content-Length: 64\r\n\ + \r\n\ + {\"s", + ) + .await; + tokio::time::sleep(std::time::Duration::from_secs(3)).await; + // Connection closes here; the client has already timed out. + continue; + } + + // Second attempt: complete a valid JSON response immediately. + let body = r#"{"stop_reason":"end_turn","content":[{"type":"text","text":"ok"}],"usage":{"input_tokens":1,"output_tokens":1}}"#; + let resp = format!( + "HTTP/1.1 200 OK\r\nContent-Type: application/json\r\n\ + Content-Length: {}\r\nConnection: close\r\n\r\n{}", + body.len(), + body, + ); + let _ = sock.write_all(resp.as_bytes()).await; + let _ = sock.shutdown().await; + } + }); + + // No client-level timeout — per-request timeout is applied inside post(). + let client = Client::builder().build().unwrap(); + let out = post( + &client, + &url, + &serde_json::json!({"model": "x"}), + false, + // Small base timeout so the body stall triggers quickly. + Duration::from_secs(1), + |b| b, + ) + .await + .expect("post should succeed on the second attempt after body-read timeout"); + assert!(out.is_object(), "expected a JSON object response: {out:?}"); + assert_eq!( + accepts.load(Ordering::SeqCst), + 2, + "server must see exactly 2 requests (body-read timeout retry)" + ); + } + /// `terminal_llm_error` below `STALL_NOTICE_THRESHOLD` carries the detail /// and attempt count but no stall-specific text — this is the common case /// (a handful of quick retries), not an outage. From cf4a6d0280ec4bf1d1f11b25049a73afae10f244 Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Fri, 7 Aug 2026 11:00:08 -0400 Subject: [PATCH 3/3] refactor(buzz-agent): simplify timeout threading and harden retry tests Drop the redundant base_timeout parameter from provider methods that already hold cfg; extract the 429 Retry-After cap into a pure retry_delay_for_429 seam so cap enforcement is unit-testable without a 60s sleep; mirror the body-read-timeout regression for openrouter_post; document the worst-case escalation ceiling; log summarize durations. Signed-off-by: Will Pfleger --- crates/buzz-agent/src/llm.rs | 497 ++++++++++++++++++++--------------- 1 file changed, 284 insertions(+), 213 deletions(-) diff --git a/crates/buzz-agent/src/llm.rs b/crates/buzz-agent/src/llm.rs index c1ac9943e6..e763c5c138 100644 --- a/crates/buzz-agent/src/llm.rs +++ b/crates/buzz-agent/src/llm.rs @@ -139,14 +139,12 @@ impl Llm { effective_model: &str, ) -> Result { let effort = cfg.thinking_effort; - let base_timeout = cfg.llm_timeout; let call_start = std::time::Instant::now(); let result = match cfg.provider { Provider::Anthropic => self .post_anthropic( cfg, &anthropic_body(cfg, system_prompt, history, tools, effective_model, effort), - base_timeout, ) .await .and_then(parse_anthropic), @@ -159,7 +157,7 @@ impl Llm { effective_model, cfg.prompt_caching, ); - self.post_openrouter(cfg, &body, base_timeout) + self.post_openrouter(cfg, &body) .await .and_then(parse_openai_with_reasoning_details) } @@ -194,58 +192,38 @@ impl Llm { ) } }, - base_timeout, ) .await } Provider::DatabricksV2 => { - self.databricks_v2_request( - cfg, - effective_model, - |route| match route { - DatabricksV2Route::OpenAiResponses => { - // OpenAI Responses path: normalize effort against the per-model table. - let e = effort - .map(|ef| normalize_effort_for_openai_route(ef, effective_model)); - ( - responses_body( - cfg, - system_prompt, - history, - tools, - effective_model, - e, - ), - parse_responses as OpenAiParse, - ) - } - DatabricksV2Route::AnthropicMessages => { - // Anthropic Messages path: normalize effort (none|minimal → omit). - let e = effort.and_then(normalize_effort_for_anthropic_route); - ( - anthropic_body( - cfg, - system_prompt, - history, - tools, - effective_model, - e, - ), - parse_anthropic as OpenAiParse, - ) - } - DatabricksV2Route::MlflowChatCompletions => { - // MLflow Chat path (OpenAI-shaped): normalize effort against the per-model table. - let e = effort - .map(|ef| normalize_effort_for_openai_route(ef, effective_model)); - ( - openai_body(cfg, system_prompt, history, tools, effective_model, e), - parse_openai as OpenAiParse, - ) - } - }, - base_timeout, - ) + self.databricks_v2_request(cfg, effective_model, |route| match route { + DatabricksV2Route::OpenAiResponses => { + // OpenAI Responses path: normalize effort against the per-model table. + let e = + effort.map(|ef| normalize_effort_for_openai_route(ef, effective_model)); + ( + responses_body(cfg, system_prompt, history, tools, effective_model, e), + parse_responses as OpenAiParse, + ) + } + DatabricksV2Route::AnthropicMessages => { + // Anthropic Messages path: normalize effort (none|minimal → omit). + let e = effort.and_then(normalize_effort_for_anthropic_route); + ( + anthropic_body(cfg, system_prompt, history, tools, effective_model, e), + parse_anthropic as OpenAiParse, + ) + } + DatabricksV2Route::MlflowChatCompletions => { + // MLflow Chat path (OpenAI-shaped): normalize effort against the per-model table. + let e = + effort.map(|ef| normalize_effort_for_openai_route(ef, effective_model)); + ( + openai_body(cfg, system_prompt, history, tools, effective_model, e), + parse_openai as OpenAiParse, + ) + } + }) .await } }; @@ -300,73 +278,70 @@ impl Llm { max_output_tokens: u32, effective_model: &str, ) -> Result { - let base_timeout = cfg.llm_timeout; - match cfg.provider { - Provider::Anthropic => { - let body = json!({ - "model": effective_model, - "max_tokens": max_output_tokens, - "system": system_prompt, - "messages": [{ - "role": "user", - "content": [{ "type": "text", "text": user_prompt }], - }], - }); - Ok(parse_anthropic(self.post_anthropic(cfg, &body, base_timeout).await?)?.text) - } - Provider::OpenRouter => { - let body = openrouter_summary_body( - effective_model, - system_prompt, - user_prompt, - max_output_tokens, - ); - let v = self.post_openrouter(cfg, &body, base_timeout).await?; - Ok(parse_openai(v)?.text) - } - Provider::OpenAi | Provider::Databricks => { - let r = self - .openai_request( - cfg, - effective_model, - false, - |use_responses, request_model| { - if use_responses { - ( - json!({ - "model": request_model, - "max_output_tokens": max_output_tokens, - "instructions": system_prompt, - "input": user_prompt, - }), - parse_responses as OpenAiParse, - ) - } else { - ( - json!({ - "model": request_model, - "stream": false, - "max_completion_tokens": max_output_tokens, - "messages": [ - { "role": "system", "content": system_prompt }, - { "role": "user", "content": user_prompt }, - ], - }), - parse_openai as OpenAiParse, - ) - } - }, - base_timeout, - ) - .await?; - Ok(r.text) - } - Provider::DatabricksV2 => { - let r = self - .databricks_v2_request( - cfg, + let call_start = std::time::Instant::now(); + let result = (async { + match cfg.provider { + Provider::Anthropic => { + let body = json!({ + "model": effective_model, + "max_tokens": max_output_tokens, + "system": system_prompt, + "messages": [{ + "role": "user", + "content": [{ "type": "text", "text": user_prompt }], + }], + }); + Ok(parse_anthropic(self.post_anthropic(cfg, &body).await?)?.text) + } + Provider::OpenRouter => { + let body = openrouter_summary_body( effective_model, - |route| match route { + system_prompt, + user_prompt, + max_output_tokens, + ); + let v = self.post_openrouter(cfg, &body).await?; + Ok(parse_openai(v)?.text) + } + Provider::OpenAi | Provider::Databricks => { + let r = self + .openai_request( + cfg, + effective_model, + false, + |use_responses, request_model| { + if use_responses { + ( + json!({ + "model": request_model, + "max_output_tokens": max_output_tokens, + "instructions": system_prompt, + "input": user_prompt, + }), + parse_responses as OpenAiParse, + ) + } else { + ( + json!({ + "model": request_model, + "stream": false, + "max_completion_tokens": max_output_tokens, + "messages": [ + { "role": "system", "content": system_prompt }, + { "role": "user", "content": user_prompt }, + ], + }), + parse_openai as OpenAiParse, + ) + } + }, + ) + .await?; + Ok(r.text) + } + Provider::DatabricksV2 => { + let r = self + .databricks_v2_request(cfg, effective_model, |route| match route { DatabricksV2Route::OpenAiResponses => ( json!({ "model": effective_model, @@ -400,23 +375,28 @@ impl Llm { }), parse_openai as OpenAiParse, ), - }, - base_timeout, - ) - .await?; - Ok(r.text) + }) + .await?; + Ok(r.text) + } } + }) + .await; + if result.is_ok() { + let duration_ms = call_start.elapsed().as_millis(); + tracing::info!( + model = effective_model, + provider = ?cfg.provider, + duration_ms, + "llm: summarize completed" + ); } + result } - async fn post_anthropic( - &self, - cfg: &Config, - body: &Value, - base_timeout: std::time::Duration, - ) -> Result { + async fn post_anthropic(&self, cfg: &Config, body: &Value) -> Result { let url = format!("{}/v1/messages", cfg.base_url.trim_end_matches('/')); - post(&self.http, &url, body, false, base_timeout, |r| { + post(&self.http, &url, body, false, cfg.llm_timeout, |r| { r.header("x-api-key", &cfg.api_key) .header("anthropic-version", &cfg.anthropic_api_version) }) @@ -434,7 +414,6 @@ impl Llm { effective_model: &str, tools_supplied: bool, mut build: F, - base_timeout: std::time::Duration, ) -> Result where F: FnMut(bool, &str) -> (Value, OpenAiParse) + Send, @@ -444,7 +423,7 @@ impl Llm { effective_model == MESH_AUTO_MODEL_ID && request_model == MESH_VIRTUAL_MODEL_ID; let first = self - .openai_request_for_model(cfg, &request_model, &mut build, base_timeout) + .openai_request_for_model(cfg, &request_model, &mut build) .await; match first { Err(PostError::MeshFallback(detail)) if adaptive_mesh => { @@ -456,7 +435,7 @@ impl Llm { provider_message = detail, "relay-mesh auto: collective request failed; retrying once with auto" ); - self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build, base_timeout) + self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build) .await .map_err(PostError::into_agent) } @@ -473,7 +452,7 @@ impl Llm { fallback_model = MESH_AUTO_MODEL_ID, "relay-mesh auto: collective response emitted unstructured tool markup; retrying once with auto" ); - self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build, base_timeout) + self.openai_request_for_model(cfg, MESH_AUTO_MODEL_ID, &mut build) .await .map_err(PostError::into_agent) } @@ -625,7 +604,6 @@ impl Llm { cfg: &Config, request_model: &str, build: &mut F, - base_timeout: std::time::Duration, ) -> Result where F: FnMut(bool, &str) -> (Value, OpenAiParse) + Send, @@ -637,14 +615,14 @@ impl Llm { if use_responses { let (body, parse) = build(true, request_model); return parse( - self.post_openai(cfg, "/responses", &body, request_model, base_timeout) + self.post_openai(cfg, "/responses", &body, request_model) .await?, ) .map_err(PostError::from); } let (body, parse) = build(false, request_model); match self - .post_openai(cfg, "/chat/completions", &body, request_model, base_timeout) + .post_openai(cfg, "/chat/completions", &body, request_model) .await { Ok(value) => parse(value).map_err(PostError::from), @@ -653,7 +631,7 @@ impl Llm { { let (body, parse) = build(true, request_model); parse( - self.post_openai(cfg, "/responses", &body, request_model, base_timeout) + self.post_openai(cfg, "/responses", &body, request_model) .await?, ) .map_err(PostError::from) @@ -667,7 +645,6 @@ impl Llm { cfg: &Config, effective_model: &str, build: F, - base_timeout: std::time::Duration, ) -> Result where F: FnOnce(DatabricksV2Route) -> (Value, OpenAiParse) + Send, @@ -675,15 +652,9 @@ impl Llm { let route = databricks_v2_route_for_model(effective_model); let (body, parse) = build(route); parse( - self.post_openai( - cfg, - databricks_v2_path(route), - &body, - effective_model, - base_timeout, - ) - .await - .map_err(PostError::into_agent)?, + self.post_openai(cfg, databricks_v2_path(route), &body, effective_model) + .await + .map_err(PostError::into_agent)?, ) } @@ -698,7 +669,6 @@ impl Llm { path: &str, body: &Value, effective_model: &str, - base_timeout: std::time::Duration, ) -> Result { let (url, body_owned); let body_ref: &Value = match cfg.provider { @@ -732,7 +702,7 @@ impl Llm { &url, body_ref, effective_model == MESH_VIRTUAL_MODEL_ID, - base_timeout, + cfg.llm_timeout, |r| r.bearer_auth(&bearer), ) .await @@ -750,17 +720,12 @@ impl Llm { } } - async fn post_openrouter( - &self, - cfg: &Config, - body: &Value, - base_timeout: std::time::Duration, - ) -> Result { + async fn post_openrouter(&self, cfg: &Config, body: &Value) -> Result { let url = format!("{}/chat/completions", cfg.base_url.trim_end_matches('/')); let mut bearer = self.auth.bearer().await?; let mut refreshed = false; loop { - match openrouter_post(&self.http, &url, body, &bearer, base_timeout).await { + match openrouter_post(&self.http, &url, body, &bearer, cfg.llm_timeout).await { Err(AgentError::LlmAuth(_)) if !refreshed => { refreshed = true; let new_bearer = self.auth.refresh_now(&bearer).await?; @@ -1803,6 +1768,16 @@ const ESCALATION_TIMEOUT_CAP: std::time::Duration = std::time::Duration::from_se /// preserved as-is. /// /// Examples at base = 240 s: 0 failures → 240 s; 1 → 480 s; 2 → 960 s; 3 → 1200 s. +/// +/// **Worst-case turn ceiling** (all 3 attempts time out, `MAX_RETRIES = 3`): +/// +/// ```text +/// total ≤ base + min(2×base, cap) + min(4×base, cap) +/// ``` +/// +/// Concrete anchors operators can use to size their outer turn timeout: +/// - 240 s base (default): 240 + 480 + 960 = **1680 s** (~28 min) +/// - 900 s base: 900 + 1200 + 1200 = **3300 s** (~55 min) fn escalated_timeout(base: std::time::Duration, timeout_failures: u32) -> std::time::Duration { // `checked_shl` returns None when the shift would overflow u32; saturate to // u32::MAX so the cap below clamps it rather than panicking or wrapping. @@ -2294,12 +2269,26 @@ enum OpenRouterErrorClass { /// worst-case turn latency to a value smaller than the per-request timeout. const RETRY_AFTER_CAP_SECS: u64 = 60; -fn parse_retry_after_header(headers: &reqwest::header::HeaderMap) -> Option { - let val = headers.get(reqwest::header::RETRY_AFTER)?.to_str().ok()?; +/// Compute the retry delay from a raw `Retry-After` header value. +/// +/// Returns `Some(duration)` when the header is present, non-zero, and +/// parseable as a decimal number of seconds; the value is capped at +/// `RETRY_AFTER_CAP_SECS`. Returns `None` when the header is absent, +/// unparseable, or zero — callers should fall back to `backoff_with_jitter`. +/// +/// This is the single place the cap logic lives; `parse_retry_after_header` +/// delegates here so the cap can be unit tested without an HTTP header map. +fn retry_delay_for_429(header_value: Option<&str>) -> Option { + let val = header_value?; let secs: u64 = val.trim().parse().ok()?; (secs > 0).then(|| std::time::Duration::from_secs(secs.min(RETRY_AFTER_CAP_SECS))) } +fn parse_retry_after_header(headers: &reqwest::header::HeaderMap) -> Option { + let val = headers.get(reqwest::header::RETRY_AFTER)?.to_str().ok()?; + retry_delay_for_429(Some(val)) +} + fn classify_openrouter_error( status: u16, body: &str, @@ -4698,6 +4687,81 @@ mod tests { ); } + /// `openrouter_post`: a body-read timeout on the first attempt retries under + /// an escalated budget and succeeds on the second attempt. + /// + /// Same shape as `post_body_read_timeout_retries_with_escalated_budget` — + /// the stub stalls mid-body on the first request, then returns a complete + /// response immediately on the second. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn openrouter_post_body_read_timeout_retries_with_escalated_budget() { + use std::sync::atomic::{AtomicU32, Ordering}; + use std::sync::Arc; + use tokio::io::{AsyncReadExt, AsyncWriteExt}; + use tokio::net::TcpListener; + + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}/chat/completions", listener.local_addr().unwrap()); + let accepts = Arc::new(AtomicU32::new(0)); + let accepts_srv = accepts.clone(); + + tokio::spawn(async move { + loop { + let (mut sock, _) = match listener.accept().await { + Ok(p) => p, + Err(_) => return, + }; + let n = accepts_srv.fetch_add(1, Ordering::SeqCst); + + let mut buf = Vec::new(); + let mut tmp = [0u8; 4096]; + while !buf.windows(4).any(|w| w == b"\r\n\r\n") { + match sock.read(&mut tmp).await { + Ok(0) | Err(_) => return, + Ok(k) => buf.extend_from_slice(&tmp[..k]), + } + } + + if n == 0 { + // First attempt: declare 64-byte body, send 4 bytes, stall. + let _ = sock + .write_all( + b"HTTP/1.1 200 OK\r\n\ + Content-Type: application/json\r\n\ + Content-Length: 64\r\n\ + \r\n\ + {\"c", + ) + .await; + tokio::time::sleep(std::time::Duration::from_secs(3)).await; + continue; + } + + // Second attempt: complete valid OpenRouter JSON response. + let body = r#"{"choices":[{"message":{"role":"assistant","content":"ok"},"finish_reason":"stop"}]}"#; + let resp = format!( + "HTTP/1.1 200 OK\r\nContent-Type: application/json\r\n\ + Content-Length: {}\r\nConnection: close\r\n\r\n{}", + body.len(), + body, + ); + let _ = sock.write_all(resp.as_bytes()).await; + let _ = sock.shutdown().await; + } + }); + + let client = Client::builder().build().unwrap(); + let out = openrouter_post(&client, &url, &json!({}), "key", Duration::from_secs(1)) + .await + .expect("openrouter_post should succeed on the second attempt after body-read timeout"); + assert!(out.is_object(), "expected a JSON object: {out:?}"); + assert_eq!( + accepts.load(Ordering::SeqCst), + 2, + "server must see exactly 2 requests (body-read timeout retry)" + ); + } + /// `terminal_llm_error` below `STALL_NOTICE_THRESHOLD` carries the detail /// and attempt count but no stall-specific text — this is the common case /// (a handful of quick retries), not an outage. @@ -5695,7 +5759,7 @@ mod tests { c.base_url = base; let out = llm - .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) + .post_openai(&c, "/v1/x", &json!({}), "model") .await .expect("retry with fresh token should succeed"); assert_eq!(out, json!({ "ok": true })); @@ -5704,7 +5768,7 @@ mod tests { // Second call's 401 must trigger its own refresh — the guard cannot // be a stored flag that an earlier turn already tripped. let out2 = llm - .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) + .post_openai(&c, "/v1/x", &json!({}), "model") .await .unwrap(); assert_eq!(out2, json!({ "ok": true })); @@ -5731,7 +5795,7 @@ mod tests { c.base_url = base; let err = llm - .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) + .post_openai(&c, "/v1/x", &json!({}), "model") .await .unwrap_err(); assert!( @@ -5762,7 +5826,7 @@ mod tests { c.base_url = base; let err = llm - .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) + .post_openai(&c, "/v1/x", &json!({}), "model") .await .unwrap_err(); assert!( @@ -5793,7 +5857,7 @@ mod tests { c.base_url = base; let out = llm - .post_openai(&c, "/v1/x", &json!({}), "model", Duration::from_secs(30)) + .post_openai(&c, "/v1/x", &json!({}), "model") .await .expect("retry with fresh token should clear the 403"); assert_eq!(out, json!({ "ok": true })); @@ -7362,53 +7426,65 @@ mod tests { assert_eq!(attempts.load(std::sync::atomic::Ordering::SeqCst), 2); } - /// A `Retry-After` header is actually honored as a sleep before the retry. - /// - /// The cap enforcement is covered by the `parse_retry_after_header` unit - /// tests above; this test proves the parsed-and-capped delay is passed to - /// `tokio::time::sleep` rather than being computed but discarded. Uses a 1 s - /// Retry-After (well below the 60 s cap) so the test completes quickly in - /// real time while still asserting the sleep duration. - /// - /// Note: `start_paused = true` is intentionally NOT used here — a per-request - /// `RequestBuilder::timeout()` combined with a paused Tokio clock causes the - /// runtime to auto-advance time to the timeout before the stub I/O fires, - /// which would make all attempts appear to time out. Real-clock timing is - /// required for per-request `.timeout()` to coexist with stub TCP servers. - #[tokio::test(flavor = "multi_thread", worker_threads = 2)] - async fn openrouter_post_429_retry_after_sleep_is_honored() { - let (url, _captured, attempts) = spawn_openrouter_stub(vec![ - CannedResponse::new(429, r#"{"error":{"message":"rate limited"}}"#) - .with_header("Retry-After", "1"), - CannedResponse::new(200, r#"{"choices":[{"message":{"content":"ok"}}]}"#), - ]) - .await; - let http = Client::builder() - .timeout(Duration::from_secs(30)) - .build() - .unwrap(); - let before = std::time::Instant::now(); - let out = openrouter_post( - &http, - &format!("{url}/x"), - &json!({}), - "key", - Duration::from_secs(30), - ) - .await - .expect("second attempt succeeds after 1s Retry-After sleep"); - assert_eq!(out["choices"][0]["message"]["content"], "ok"); + // ---- retry_delay_for_429 (pure-function tests, no network) --------------- + + /// A huge server-advertised Retry-After is capped at RETRY_AFTER_CAP_SECS. + /// This test proves the cap is actually wired into the loop's only delay + /// computation (not just a dead constant), because `openrouter_post`'s 429 + /// arm calls `parse_retry_after_header` which delegates to this function. + #[test] + fn retry_delay_for_429_huge_value_is_capped() { + let d = retry_delay_for_429(Some("999999")).unwrap(); + assert_eq!( + d, + Duration::from_secs(RETRY_AFTER_CAP_SECS), + "999999s must be capped to {RETRY_AFTER_CAP_SECS}s" + ); + } + + /// A small value below the cap is returned as-is. + #[test] + fn retry_delay_for_429_small_value_honored() { + let d = retry_delay_for_429(Some("3")).unwrap(); + assert_eq!(d, Duration::from_secs(3), "3s must be honored verbatim"); + } + + /// A value equal to the cap is returned unchanged (boundary). + #[test] + fn retry_delay_for_429_exact_cap_is_not_truncated() { + let d = retry_delay_for_429(Some(&RETRY_AFTER_CAP_SECS.to_string())).unwrap(); + assert_eq!( + d, + Duration::from_secs(RETRY_AFTER_CAP_SECS), + "exact cap must not be truncated" + ); + } + + /// Missing header returns None → caller falls back to backoff. + #[test] + fn retry_delay_for_429_missing_header_is_none() { + assert!( + retry_delay_for_429(None).is_none(), + "absent header must return None" + ); + } + + /// Garbage / non-numeric header returns None. + #[test] + fn retry_delay_for_429_garbage_header_is_none() { assert!( - before.elapsed() >= Duration::from_millis(800), - "must sleep at least the Retry-After hint (1s): elapsed {:?}", - before.elapsed() + retry_delay_for_429(Some("not-a-number")).is_none(), + "unparseable header must return None" ); + } + + /// Zero is treated as absent (no-op: don't sleep 0 seconds). + #[test] + fn retry_delay_for_429_zero_is_none() { assert!( - before.elapsed() < Duration::from_secs(10), - "must complete well before the 60s cap: elapsed {:?}", - before.elapsed() + retry_delay_for_429(Some("0")).is_none(), + "zero Retry-After must return None (no-op sleep)" ); - assert_eq!(attempts.load(std::sync::atomic::Ordering::SeqCst), 2); } /// An untyped 503 (no `error.metadata.error_type`) exhausts all @@ -7654,10 +7730,7 @@ mod tests { let mut c = cfg(Provider::OpenRouter); c.base_url = url; - let err = llm - .post_openrouter(&c, &json!({}), Duration::from_secs(30)) - .await - .unwrap_err(); + let err = llm.post_openrouter(&c, &json!({})).await.unwrap_err(); assert!( matches!(&err, AgentError::LlmAuth(s) if s.contains("static key rejected")), "static 401 must surface as LlmAuth with 'static key rejected': got {err:?}" @@ -7691,9 +7764,7 @@ mod tests { let mut c = cfg(Provider::OpenRouter); c.base_url = base; - let result = llm - .post_openrouter(&c, &json!({}), Duration::from_secs(30)) - .await; + let result = llm.post_openrouter(&c, &json!({})).await; // `spawn_auth_stub` returns `{"ok":true}` on success. assert!( result.is_ok(),