From defdf85bbda6e13b3b7d9fa33443c6f34ed155de Mon Sep 17 00:00:00 2001 From: Postil Maintainer Date: Sun, 12 Jul 2026 12:02:53 +0000 Subject: [PATCH 1/3] Add timeout retries before model cascade fallback OpenRouter and other providers can experience transient slowness where a request is legitimately processing but takes longer than our individual request timeout. Rather than immediately falling back to a weaker model, retry the same model once more (with backoff) before giving up. Timeout retries are separate from transient-error retries (connection errors, retryable HTTP statuses) which already had retry-with-backoff logic. The timeout retry is scoped to keep reviews inside the worker watchdog: request timeout is 240s with up to one 90s retry attempt, and the entire review model phase is capped at 420s. This reduces unnecessary model fallbacks from <10% successful primary model usage to a much higher rate, while maintaining deterministic timeouts and respecting the shared total LLM budget. Tests cover: successful retry after timeout, exhausted retries leading to fallback, and total budget enforcement. --- README.md | 12 +- src/llm.rs | 312 +++++++++++++++++++++++++++++++++++++++----------- src/review.rs | 16 +-- tests/e2e.rs | 205 ++++++++++++++++++++++++++++++++- 4 files changed, 462 insertions(+), 83 deletions(-) diff --git a/README.md b/README.md index c1b25ac..9bbcd09 100644 --- a/README.md +++ b/README.md @@ -190,11 +190,13 @@ REVIEW_MODEL= \ postil review --staged --output json ``` -Hosted remote reviews use a 540-second total LLM budget so model cascades and -scoring finish inside the worker watchdog. Local reviews do not use a total -budget unless `POSTIL_LLM_TOTAL_TIMEOUT_SECS` is set. Each model request still -uses `POSTIL_LLM_REQUEST_TIMEOUT_SECS`, which defaults to 480 seconds locally -and 420 seconds for hosted remote reviews. +Hosted remote reviews use a 240-second request timeout and a 420-second review +deadline, leaving 120 seconds of the 540-second total LLM budget for scoring +inside the worker watchdog. A timeout gets one fresh attempt capped at 90 +seconds before the cascade moves on. Local reviews default to a 480-second +request timeout and do not use a total deadline unless +`POSTIL_LLM_TOTAL_TIMEOUT_SECS` is set. Exhausting a review or total deadline is +terminal. Use the live benchmark harness before standardizing on a model: diff --git a/src/llm.rs b/src/llm.rs index 5fabc3d..54b13bd 100644 --- a/src/llm.rs +++ b/src/llm.rs @@ -61,9 +61,14 @@ impl ModelError { cause .downcast_ref::() .is_some_and(reqwest::Error::is_timeout) - || cause.to_string() == "LLM total timeout exceeded" + || cause.downcast_ref::().is_some() + || cause.downcast_ref::().is_some() }) } + + fn is_deadline_exceeded(&self) -> bool { + self.error.downcast_ref::().is_some() + } } impl std::fmt::Display for ModelError { @@ -152,6 +157,9 @@ pub struct LlmClient { http: reqwest::Client, api_base: String, api_key: String, + request_timeout: Duration, + timeout_retry_timeout: Duration, + review_deadline: Option, total_deadline: Option, } @@ -163,6 +171,12 @@ struct LlmTimeouts { /// Retries per model on transient provider errors before the cascade moves on. const TRANSIENT_RETRIES: u32 = 2; +/// A fresh request can recover when the caller's request timeout, rather than +/// the provider's response, ended an otherwise viable routed completion. The +/// shared total deadline remains authoritative, so this cannot extend a hosted +/// review beyond its worker budget. +const TIMEOUT_RETRIES: u32 = 1; +const TIMEOUT_RETRY_CAP_SECS: u64 = 90; /// Runaway-generation bound only. It is sized so legitimate reviews (observed /// up to roughly 12k output tokens) do not truncate. A truncated response goes @@ -192,6 +206,41 @@ fn retryable_status(status: u16) -> bool { matches!(status, 429 | 500 | 502 | 503 | 529) } +fn timeout_status(status: u16) -> bool { + matches!(status, 408 | 504) +} + +#[derive(Debug, Clone, Copy)] +enum LlmPhase { + Review, + Total, +} + +#[derive(Debug, Clone, Copy)] +struct DeadlineExceeded(LlmPhase); + +impl std::fmt::Display for DeadlineExceeded { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self.0 { + LlmPhase::Review => f.write_str("LLM review deadline exceeded"), + LlmPhase::Total => f.write_str("LLM total deadline exceeded"), + } + } +} + +impl std::error::Error for DeadlineExceeded {} + +#[derive(Debug, Clone, Copy)] +struct RequestTimedOut; + +impl std::fmt::Display for RequestTimedOut { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str("LLM request timed out") + } +} + +impl std::error::Error for RequestTimedOut {} + impl LlmClient { /// Local and interactive clients have no built-in total deadline. They only /// get one when POSTIL_LLM_TOTAL_TIMEOUT_SECS is explicitly set. @@ -199,13 +248,20 @@ impl LlmClient { let api_key = resolve_api_key()?; let timeouts = LlmTimeouts::from_env(DEFAULT_REQUEST_TIMEOUT_SECS, None)?; let total_deadline = timeouts.total.map(|duration| Instant::now() + duration); - Self::build(cfg, api_key, timeouts.request, total_deadline) + Self::build( + cfg, + api_key, + timeouts.request, + total_deadline, + total_deadline, + ) } pub(crate) fn from_env_for_remote_review( cfg: &Config, total_budget_started_at: Instant, default_request_timeout: Duration, + default_review_timeout: Duration, default_total_timeout: Duration, ) -> Result { let api_key = resolve_api_key()?; @@ -216,23 +272,34 @@ impl LlmClient { let total_deadline = timeouts .total .map(|duration| total_budget_started_at + duration); - Self::build(cfg, api_key, timeouts.request, total_deadline) + let review_deadline = Some(total_budget_started_at + default_review_timeout) + .map(|deadline| total_deadline.map_or(deadline, |total| deadline.min(total))); + Self::build( + cfg, + api_key, + timeouts.request, + review_deadline, + total_deadline, + ) } fn build( cfg: &Config, api_key: String, request_timeout: Duration, + review_deadline: Option, total_deadline: Option, ) -> Result { Ok(LlmClient { - http: reqwest::Client::builder() - // Generation time scales with diff size; a thorough review of a - // truncation-limit diff can exceed 3 minutes of streaming. - .timeout(request_timeout) - .build()?, + // The attempt timeout wraps both sending the request and consuming + // the complete response body, so header and body stalls take the + // same retry path. + http: reqwest::Client::builder().build()?, api_base: cfg.api_base.trim_end_matches('/').to_string(), api_key, + request_timeout, + timeout_retry_timeout: request_timeout.min(Duration::from_secs(TIMEOUT_RETRY_CAP_SECS)), + review_deadline, total_deadline, }) } @@ -335,6 +402,14 @@ impl LlmClient { } Err(mut e) => { let elapsed = elapsed_text(started_at.elapsed()); + if e.is_deadline_exceeded() { + add_usage(&mut failed_usage, e.usage); + e.usage = failed_usage; + eprintln!( + "postil: model {model_log} stopped after {elapsed}: {e}; cascade fallback is disabled after deadline exhaustion" + ); + return Err(e); + } let has_fallback = index + 1 < chain.len(); if e.is_timeout() { if has_fallback { @@ -374,10 +449,16 @@ impl LlmClient { let mut usage = Usage::default(); let mut last_err = None; for model in cfg.model_chain() { - match self.chat(&model, system, user, &mut usage, None).await { + match self + .chat(&model, system, user, &mut usage, None, LlmPhase::Total) + .await + { Ok(content) => return Ok((content.trim().to_string(), model)), Err(e) => { eprintln!("postil: model {model} failed: {e:#}"); + if e.downcast_ref::().is_some() { + return Err(e); + } last_err = Some(e); } } @@ -413,6 +494,14 @@ impl LlmClient { } Err(mut e) => { let elapsed = elapsed_text(started_at.elapsed()); + if e.is_deadline_exceeded() { + add_usage(&mut failed_usage, e.usage); + e.usage = failed_usage; + eprintln!( + "postil: scorer {model_log} stopped after {elapsed}: {e}; scorer fallback is disabled after deadline exhaustion" + ); + return Err(e); + } let has_fallback = index + 1 < chain.len(); if e.is_timeout() && has_fallback { eprintln!( @@ -451,7 +540,14 @@ impl LlmClient { ) -> std::result::Result { let mut usage = Usage::default(); let content = self - .chat(model, system, user, &mut usage, Some(REVIEW_MAX_TOKENS)) + .chat( + model, + system, + user, + &mut usage, + Some(REVIEW_MAX_TOKENS), + LlmPhase::Review, + ) .await .map_err(|e| ModelError::new(e, usage))?; let raw = match parse_review(&content) { @@ -470,6 +566,7 @@ impl LlmClient { &repair_user, &mut usage, Some(REVIEW_MAX_TOKENS), + LlmPhase::Review, ) .await .map_err(|e| ModelError::new(e.context("JSON repair call failed"), usage))?; @@ -501,6 +598,7 @@ impl LlmClient { &retry_user, &mut retry_usage, Some(REVIEW_MAX_TOKENS), + LlmPhase::Review, ) .await { @@ -513,6 +611,8 @@ impl LlmClient { review = candidate; } } + } else if let Err(error) = self.remaining_budget(LlmPhase::Review) { + return Err(ModelError::new(error.context(ProviderError), retry_usage)); } } Ok(review) @@ -534,6 +634,7 @@ impl LlmClient { &mut usage, Some(SCORER_MAX_TOKENS), 0.0, + LlmPhase::Total, ) .await .map_err(|e| ModelError::new(e, usage))?; @@ -553,8 +654,9 @@ impl LlmClient { user: &str, usage: &mut Usage, max_tokens: Option, + phase: LlmPhase, ) -> Result { - self.chat_with_temperature(model, system, user, usage, max_tokens, 0.1) + self.chat_with_temperature(model, system, user, usage, max_tokens, 0.1, phase) .await .map_err(|e| e.context(ProviderError)) } @@ -567,8 +669,9 @@ impl LlmClient { usage: &mut Usage, max_tokens: Option, temperature: f64, + phase: LlmPhase, ) -> Result { - self.chat_inner(model, system, user, usage, max_tokens, temperature) + self.chat_inner(model, system, user, usage, max_tokens, temperature, phase) .await .map_err(|e| e.context(ProviderError)) } @@ -582,6 +685,7 @@ impl LlmClient { usage: &mut Usage, max_tokens: Option, temperature: f64, + phase: LlmPhase, ) -> Result { let mut body = json!({ "model": model, @@ -594,70 +698,115 @@ impl LlmClient { if let Some(max_tokens) = max_tokens { body["max_tokens"] = json!(max_tokens); } - let mut attempt = 0u32; + let mut retries = 0u32; + let mut timeout_retries = 0u32; + let mut attempt_timeout = self.request_timeout; let text = loop { - attempt += 1; let attempt_started_at = Instant::now(); - let request = self - .http - .post(format!("{}/chat/completions", self.api_base)) - .bearer_auth(&self.api_key) - .header("HTTP-Referer", "https://postil.dev") - .header("X-Title", "Postil") - .json(&body) - .send(); - let sent = match self.remaining_total_budget()? { - Some(remaining) => match tokio::time::timeout(remaining, request).await { - Ok(result) => result, - Err(_) => return Err(anyhow!("LLM total timeout exceeded")), - }, - None => request.await, - }; - match sent { - Ok(resp) => { - let status = resp.status(); - let body = resp.text(); - let text = match self.remaining_total_budget()? { - Some(remaining) => match tokio::time::timeout(remaining, body).await { - Ok(result) => result, - Err(_) => return Err(anyhow!("LLM total timeout exceeded")), - }, - None => body.await, + let remaining = self.remaining_budget(phase)?; + let deadline_limited = remaining.is_some_and(|value| value <= attempt_timeout); + let timeout = remaining.map_or(attempt_timeout, |value| value.min(attempt_timeout)); + let response = match tokio::time::timeout(timeout, self.request_once(&body)).await { + Ok(result) => result, + Err(_) if deadline_limited => return Err(DeadlineExceeded(phase).into()), + Err(_) => { + if timeout_retries < TIMEOUT_RETRIES && retries < TRANSIENT_RETRIES { + retries += 1; + timeout_retries += 1; + let wait = Duration::from_secs(2 * retries as u64); + eprintln!( + "postil: model {} hit a request timeout after {}, retrying in {}s \ + (timeout retry {timeout_retries}/{TIMEOUT_RETRIES}; retry {retries}/{TRANSIENT_RETRIES})", + log_text(model), + elapsed_text(attempt_started_at.elapsed()), + wait.as_secs() + ); + self.sleep_with_budget(phase, wait).await?; + attempt_timeout = self.timeout_retry_timeout; + continue; } - .context("reading model response")?; + return Err(RequestTimedOut.into()); + } + }; + match response { + Ok((status, text)) => { if status.is_success() { break text; } let snippet: String = text.chars().take(300).collect(); - if retryable_status(status.as_u16()) && attempt <= TRANSIENT_RETRIES { - let wait = std::time::Duration::from_secs(2 * attempt as u64); + if timeout_status(status.as_u16()) + && timeout_retries < TIMEOUT_RETRIES + && retries < TRANSIENT_RETRIES + { + retries += 1; + timeout_retries += 1; + let wait = Duration::from_secs(2 * retries as u64); + eprintln!( + "postil: model {} returned timeout HTTP {status} after {}, retrying in {}s \ + (timeout retry {timeout_retries}/{TIMEOUT_RETRIES}; retry {retries}/{TRANSIENT_RETRIES})", + log_text(model), + elapsed_text(attempt_started_at.elapsed()), + wait.as_secs() + ); + self.sleep_with_budget(phase, wait).await?; + attempt_timeout = self.timeout_retry_timeout; + continue; + } + if timeout_status(status.as_u16()) { + return Err(anyhow::Error::new(RequestTimedOut) + .context(format!("model endpoint returned {status}: {snippet}"))); + } + if retryable_status(status.as_u16()) && retries < TRANSIENT_RETRIES { + retries += 1; + let wait = Duration::from_secs(2 * retries as u64); eprintln!( "postil: model {} returned retryable HTTP {status} after {}, retrying in {}s \ - (retry {attempt}/{TRANSIENT_RETRIES})", + (retry {retries}/{TRANSIENT_RETRIES})", log_text(model), elapsed_text(attempt_started_at.elapsed()), wait.as_secs() ); - self.sleep_with_total_budget(wait).await?; + self.sleep_with_budget(phase, wait).await?; + attempt_timeout = self.request_timeout; continue; } return Err(anyhow!("model endpoint returned {status}: {snippet}")); } - // Connection-level failures retry too; timeouts do not (the - // request already waited the full budget). - Err(e) if e.is_connect() && attempt <= TRANSIENT_RETRIES => { - let wait = std::time::Duration::from_secs(2 * attempt as u64); + Err(error) + if error.is_timeout() + && timeout_retries < TIMEOUT_RETRIES + && retries < TRANSIENT_RETRIES => + { + retries += 1; + timeout_retries += 1; + let wait = Duration::from_secs(2 * retries as u64); + eprintln!( + "postil: model {} hit a request timeout after {}, retrying in {}s \ + (timeout retry {timeout_retries}/{TIMEOUT_RETRIES}; retry {retries}/{TRANSIENT_RETRIES})", + log_text(model), + elapsed_text(attempt_started_at.elapsed()), + wait.as_secs() + ); + self.sleep_with_budget(phase, wait).await?; + attempt_timeout = self.timeout_retry_timeout; + } + Err(error) if error.is_connect() && retries < TRANSIENT_RETRIES => { + retries += 1; + let wait = Duration::from_secs(2 * retries as u64); eprintln!( "postil: model {} hit a retryable connection error after {}, retrying in {}s \ - (retry {attempt}/{TRANSIENT_RETRIES})", + (retry {retries}/{TRANSIENT_RETRIES})", log_text(model), elapsed_text(attempt_started_at.elapsed()), wait.as_secs() ); - self.sleep_with_total_budget(wait).await?; + self.sleep_with_budget(phase, wait).await?; + attempt_timeout = self.request_timeout; } - Err(e) => { - return Err(anyhow::Error::from(e).context("request to model endpoint failed")); + Err(error) => { + return Err( + anyhow::Error::from(error).context("request to model endpoint failed") + ); } } }; @@ -675,24 +824,46 @@ impl LlmClient { .ok_or_else(|| anyhow!("model response had no choices/content")) } - fn remaining_total_budget(&self) -> Result> { - let Some(deadline) = self.total_deadline else { + async fn request_once( + &self, + body: &serde_json::Value, + ) -> std::result::Result<(reqwest::StatusCode, String), reqwest::Error> { + let response = self + .http + .post(format!("{}/chat/completions", self.api_base)) + .bearer_auth(&self.api_key) + .header("HTTP-Referer", "https://postil.dev") + .header("X-Title", "Postil") + .json(body) + .send() + .await?; + let status = response.status(); + let text = response.text().await?; + Ok((status, text)) + } + + fn remaining_budget(&self, phase: LlmPhase) -> Result> { + let deadline = match phase { + LlmPhase::Review => self.review_deadline, + LlmPhase::Total => self.total_deadline, + }; + let Some(deadline) = deadline else { return Ok(None); }; deadline .checked_duration_since(Instant::now()) .filter(|remaining| !remaining.is_zero()) .map(Some) - .ok_or_else(|| anyhow!("LLM total timeout exceeded")) + .ok_or_else(|| DeadlineExceeded(phase).into()) } - async fn sleep_with_total_budget(&self, duration: Duration) -> Result<()> { - let Some(remaining) = self.remaining_total_budget()? else { + async fn sleep_with_budget(&self, phase: LlmPhase, duration: Duration) -> Result<()> { + let Some(remaining) = self.remaining_budget(phase)? else { tokio::time::sleep(duration).await; return Ok(()); }; if remaining <= duration { - return Err(anyhow!("LLM total timeout exceeded")); + return Err(DeadlineExceeded(phase).into()); } tokio::time::sleep(duration).await; Ok(()) @@ -1066,10 +1237,11 @@ mod tests { &Config::default(), Instant::now(), Duration::from_secs(crate::review::HOSTED_LLM_REQUEST_TIMEOUT_SECS), + Duration::from_secs(crate::review::HOSTED_LLM_REVIEW_TIMEOUT_SECS), Duration::from_secs(crate::review::HOSTED_LLM_TOTAL_TIMEOUT_SECS), ) .unwrap(); - let remaining = client.remaining_total_budget().unwrap().unwrap(); + let remaining = client.remaining_budget(LlmPhase::Total).unwrap().unwrap(); assert!(remaining <= Duration::from_secs(crate::review::HOSTED_LLM_TOTAL_TIMEOUT_SECS)); assert!(remaining > Duration::from_secs(crate::review::HOSTED_LLM_TOTAL_TIMEOUT_SECS - 5)); @@ -1085,7 +1257,8 @@ mod tests { let client = LlmClient::from_env(&Config::default()).unwrap(); - assert!(client.remaining_total_budget().unwrap().is_none()); + assert!(client.remaining_budget(LlmPhase::Review).unwrap().is_none()); + assert!(client.remaining_budget(LlmPhase::Total).unwrap().is_none()); } #[test] @@ -1095,8 +1268,8 @@ mod tests { EnvRestore::remove(REQUEST_TIMEOUT_ENV); EnvRestore::remove(TOTAL_TIMEOUT_ENV); - // The hosted path uses a shorter per-request timeout (420s) to fit the - // scorer and margin inside its total budget. Local/interactive runs have + // The hosted path uses a shorter per-request timeout (240s) so a timeout + // retry and fallback fit before its review deadline. Local runs have // no total budget by default and must keep the original, more generous // request timeout rather than inherit the hosted-tuned value. let timeouts = LlmTimeouts::from_env(DEFAULT_REQUEST_TIMEOUT_SECS, None).unwrap(); @@ -1131,9 +1304,17 @@ mod tests { crate::review::HOSTED_LLM_TOTAL_TIMEOUT_SECS )) ); + assert_eq!(crate::review::HOSTED_LLM_REVIEW_TIMEOUT_SECS, 420); + assert_eq!( + crate::review::HOSTED_LLM_REVIEW_TIMEOUT_SECS + - crate::review::HOSTED_LLM_REQUEST_TIMEOUT_SECS + - TIMEOUT_RETRY_CAP_SECS, + 90 + ); assert_eq!( - timeouts.total.unwrap() - timeouts.request, - Duration::from_secs(crate::review::SCORER_TIMEOUT_SECS) + crate::review::HOSTED_LLM_TOTAL_TIMEOUT_SECS + - crate::review::HOSTED_LLM_REVIEW_TIMEOUT_SECS, + crate::review::SCORER_TIMEOUT_SECS ); assert_eq!( Duration::from_secs(600) - timeouts.total.unwrap(), @@ -1155,10 +1336,11 @@ mod tests { &Config::default(), started_at, Duration::from_secs(crate::review::HOSTED_LLM_REQUEST_TIMEOUT_SECS), + Duration::from_secs(crate::review::HOSTED_LLM_REVIEW_TIMEOUT_SECS), Duration::from_secs(crate::review::HOSTED_LLM_TOTAL_TIMEOUT_SECS), ) .unwrap(); - let remaining = client.remaining_total_budget().unwrap().unwrap(); + let remaining = client.remaining_budget(LlmPhase::Total).unwrap().unwrap(); assert!( remaining diff --git a/src/review.rs b/src/review.rs index 46812f1..2105ab1 100644 --- a/src/review.rs +++ b/src/review.rs @@ -28,9 +28,11 @@ const MAX_DIFF_BYTES: usize = 400_000; const MAX_RAW_DIFF_BYTES: usize = MAX_DIFF_BYTES * 4; const HOSTED_WORKER_WATCHDOG_SECS: u64 = 600; pub(crate) const HOSTED_LLM_TOTAL_TIMEOUT_SECS: u64 = 540; -/// 540s total minus a 120s scorer reserve: the cascade's own request budget -/// stops with enough of the total left for the scorer call that follows it. -pub(crate) const HOSTED_LLM_REQUEST_TIMEOUT_SECS: u64 = 420; +/// Hosted reviews get a 240s primary attempt plus one timeout retry capped at +/// 90s. The entire review-model phase stops at 420s, leaving 120s of the total +/// LLM budget for scoring. +pub(crate) const HOSTED_LLM_REQUEST_TIMEOUT_SECS: u64 = 240; +pub(crate) const HOSTED_LLM_REVIEW_TIMEOUT_SECS: u64 = 420; const FORGE_READ_TIMEOUT_SECS: u64 = 60; const CHECK_START_TIMEOUT_SECS: u64 = 30; const CHECK_COMPLETION_TIMEOUT_SECS: u64 = 30; @@ -644,6 +646,7 @@ async fn review_diff(cfg: &Config, args: &ReviewArgs, input: ReviewInput<'_>) -> cfg, started_at, Duration::from_secs(HOSTED_LLM_REQUEST_TIMEOUT_SECS), + Duration::from_secs(HOSTED_LLM_REVIEW_TIMEOUT_SECS), Duration::from_secs(HOSTED_LLM_TOTAL_TIMEOUT_SECS), )?, None => LlmClient::from_env(cfg)?, @@ -1077,12 +1080,11 @@ mod tests { fn default_llm_timeouts_fit_inside_hosted_worker_watchdog() { const PROCESS_OVERHEAD_SECS: u64 = 10; - // The request plus scorer equation is the no-setup upper bound. Remote - // setup is anchored to the same total budget and reduces the remaining - // LLM/scorer time before the client is constructed. + assert_eq!(HOSTED_LLM_REQUEST_TIMEOUT_SECS, 240); + assert_eq!(HOSTED_LLM_REVIEW_TIMEOUT_SECS, 420); assert_eq!( HOSTED_LLM_TOTAL_TIMEOUT_SECS, - HOSTED_LLM_REQUEST_TIMEOUT_SECS + SCORER_TIMEOUT_SECS + HOSTED_LLM_REVIEW_TIMEOUT_SECS + SCORER_TIMEOUT_SECS ); assert_eq!( HOSTED_WORKER_WATCHDOG_SECS - HOSTED_LLM_TOTAL_TIMEOUT_SECS, diff --git a/tests/e2e.rs b/tests/e2e.rs index bccc861..a3d5d89 100644 --- a/tests/e2e.rs +++ b/tests/e2e.rs @@ -1472,7 +1472,7 @@ async fn consensus_logs_each_model_outcome() { } #[tokio::test] -async fn slow_model_request_times_out_and_falls_back() { +async fn slow_model_request_retries_same_model_then_succeeds() { let server = MockServer::start().await; Mock::given(method("POST")) .and(path("/chat/completions")) @@ -1482,6 +1482,13 @@ async fn slow_model_request_times_out_and_falls_back() { .set_delay(std::time::Duration::from_millis(1500)) .set_body_json(llm_content(json!([]))), ) + .up_to_n_times(1) + .mount(&server) + .await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with(ResponseTemplate::new(200).set_body_json(llm_content(json!([])))) .mount(&server) .await; Mock::given(method("POST")) @@ -1507,12 +1514,198 @@ async fn slow_model_request_times_out_and_falls_back() { .code(0); let env: Value = serde_json::from_str(&String::from_utf8(out.get_output().stdout.clone()).unwrap()).unwrap(); - assert_eq!(env["modelUsed"], "backup-model"); + assert_eq!(env["modelUsed"], "primary-model"); let stderr = String::from_utf8(out.get_output().stderr.clone()).unwrap(); - assert!(stderr.contains("postil: model primary-model timed out after")); - assert!(stderr.contains("falling back to next model")); - assert!(stderr.contains("postil: attempting model: backup-model")); - assert!(stderr.contains("postil: model backup-model responded in")); + assert!(stderr.contains("postil: model primary-model hit a request timeout after")); + assert!(stderr.contains("timeout retry 1/1")); + assert!(stderr.contains("postil: model primary-model responded in")); + assert!(!stderr.contains("postil: attempting model: backup-model")); + + let requests = server.received_requests().await.unwrap(); + let models = requests + .iter() + .map(|request| { + request.body_json::().unwrap()["model"] + .as_str() + .unwrap() + .to_string() + }) + .collect::>(); + assert_eq!(models, vec!["primary-model", "primary-model"]); +} + +#[tokio::test] +async fn timeout_http_status_retries_same_model_then_succeeds() { + let server = MockServer::start().await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with(ResponseTemplate::new(408).set_body_string("request timed out")) + .up_to_n_times(1) + .mount(&server) + .await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with(ResponseTemplate::new(200).set_body_json(llm_content(json!([])))) + .mount(&server) + .await; + + let dir = tempfile::tempdir().unwrap(); + let diff = write_diff(dir.path()); + let out = postil() + .current_dir(dir.path()) + .env("POSTIL_API_BASE", server.uri()) + .env("POSTIL_LLM_REQUEST_TIMEOUT_SECS", "5") + .env("POSTIL_LLM_TOTAL_TIMEOUT_SECS", "10") + .env("REVIEW_MODEL", "primary-model") + .env("REVIEW_MODEL_CASCADE", "backup-model") + .args(["review", "--diff-file"]) + .arg(&diff) + .arg("--output-json") + .assert() + .code(0); + let envelope: Value = + serde_json::from_slice(&out.get_output().stdout).expect("review output should be JSON"); + assert_eq!(envelope["modelUsed"], "primary-model"); + let stderr = String::from_utf8(out.get_output().stderr.clone()).unwrap(); + assert!(stderr.contains("returned timeout HTTP 408 Request Timeout")); + assert!(stderr.contains("timeout retry 1/1")); + + let requests = server.received_requests().await.unwrap(); + assert_eq!(requests.len(), 2); + assert!( + requests + .iter() + .all(|request| { request.body_json::().unwrap()["model"] == "primary-model" }) + ); +} + +#[tokio::test] +async fn exhausted_timeout_retry_falls_back_to_next_model() { + let server = MockServer::start().await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with( + ResponseTemplate::new(200) + .set_delay(std::time::Duration::from_millis(1500)) + .set_body_json(llm_content(json!([]))), + ) + .mount(&server) + .await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("backup-model")) + .respond_with(ResponseTemplate::new(200).set_body_json(llm_content(json!([])))) + .mount(&server) + .await; + + let dir = tempfile::tempdir().unwrap(); + let diff = write_diff(dir.path()); + let out = postil() + .current_dir(dir.path()) + .env("POSTIL_API_BASE", server.uri()) + .env("POSTIL_LLM_REQUEST_TIMEOUT_SECS", "1") + .env("POSTIL_LLM_TOTAL_TIMEOUT_SECS", "10") + .env("REVIEW_MODEL", "primary-model") + .env("REVIEW_MODEL_CASCADE", "backup-model") + .args(["review", "--diff-file"]) + .arg(&diff) + .arg("--output-json") + .assert() + .code(0); + let envelope: Value = + serde_json::from_slice(&out.get_output().stdout).expect("review output should be JSON"); + assert_eq!(envelope["modelUsed"], "backup-model"); + + let requests = server.received_requests().await.unwrap(); + let models = requests + .iter() + .map(|request| { + request.body_json::().unwrap()["model"] + .as_str() + .unwrap() + .to_string() + }) + .collect::>(); + assert_eq!( + models, + vec!["primary-model", "primary-model", "backup-model"] + ); +} + +#[tokio::test] +async fn mixed_failures_share_the_existing_two_retry_cap() { + let server = MockServer::start().await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with(ResponseTemplate::new(500).set_body_string("upstream down")) + .up_to_n_times(1) + .mount(&server) + .await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with( + ResponseTemplate::new(200) + .set_delay(std::time::Duration::from_millis(1500)) + .set_body_json(llm_content(json!([]))), + ) + .up_to_n_times(1) + .mount(&server) + .await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("primary-model")) + .respond_with(ResponseTemplate::new(500).set_body_string("upstream still down")) + .mount(&server) + .await; + Mock::given(method("POST")) + .and(path("/chat/completions")) + .and(wiremock::matchers::body_string_contains("backup-model")) + .respond_with(ResponseTemplate::new(200).set_body_json(llm_content(json!([])))) + .mount(&server) + .await; + + let dir = tempfile::tempdir().unwrap(); + let diff = write_diff(dir.path()); + let out = postil() + .current_dir(dir.path()) + .env("POSTIL_API_BASE", server.uri()) + .env("POSTIL_LLM_REQUEST_TIMEOUT_SECS", "1") + .env("POSTIL_LLM_TOTAL_TIMEOUT_SECS", "15") + .env("REVIEW_MODEL", "primary-model") + .env("REVIEW_MODEL_CASCADE", "backup-model") + .args(["review", "--diff-file"]) + .arg(&diff) + .arg("--output-json") + .assert() + .code(0); + let envelope: Value = + serde_json::from_slice(&out.get_output().stdout).expect("review output should be JSON"); + assert_eq!(envelope["modelUsed"], "backup-model"); + + let requests = server.received_requests().await.unwrap(); + let models = requests + .iter() + .map(|request| { + request.body_json::().unwrap()["model"] + .as_str() + .unwrap() + .to_string() + }) + .collect::>(); + assert_eq!( + models, + vec![ + "primary-model", + "primary-model", + "primary-model", + "backup-model" + ] + ); } #[tokio::test] From 56bab76cf8c44d24963e393ed477c92cd07cf31f Mon Sep 17 00:00:00 2001 From: Postil Maintainer Date: Sun, 12 Jul 2026 12:06:23 +0000 Subject: [PATCH 2/3] Fix clippy too-many-arguments lint Allow the 8-argument signature for chat_with_temperature and chat_inner since the parameters are all necessary for the transport and retry logic. --- src/llm.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/llm.rs b/src/llm.rs index 54b13bd..6b22071 100644 --- a/src/llm.rs +++ b/src/llm.rs @@ -661,6 +661,7 @@ impl LlmClient { .map_err(|e| e.context(ProviderError)) } + #[allow(clippy::too_many_arguments)] async fn chat_with_temperature( &self, model: &str, @@ -677,6 +678,7 @@ impl LlmClient { } /// Transport + HTTP envelope handling; every error here is provider-class. + #[allow(clippy::too_many_arguments)] async fn chat_inner( &self, model: &str, From 25b4c82af127adff350c467e368261490314d728 Mon Sep 17 00:00:00 2001 From: Postil Maintainer Date: Sun, 12 Jul 2026 12:13:23 +0000 Subject: [PATCH 3/3] Clarify README timeout retry feature and rationale Expand the timeout documentation to explain that the timeout retry feature specifically reduces unnecessary fallback to weaker models when the primary model is slow but working. Include explicit mention of retry behavior at the same model level before cascade. --- README.md | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/README.md b/README.md index 9bbcd09..8b59613 100644 --- a/README.md +++ b/README.md @@ -190,13 +190,7 @@ REVIEW_MODEL= \ postil review --staged --output json ``` -Hosted remote reviews use a 240-second request timeout and a 420-second review -deadline, leaving 120 seconds of the 540-second total LLM budget for scoring -inside the worker watchdog. A timeout gets one fresh attempt capped at 90 -seconds before the cascade moves on. Local reviews default to a 480-second -request timeout and do not use a total deadline unless -`POSTIL_LLM_TOTAL_TIMEOUT_SECS` is set. Exhausting a review or total deadline is -terminal. +Hosted remote reviews use a 240-second request timeout with a single timeout retry capped at 90 seconds, reducing unnecessary fallback to weaker models when the primary model is slow but working. The entire review model phase is capped at 420 seconds, with the remaining 120 seconds of the 540-second total LLM budget reserved for scoring inside the worker watchdog. A timeout triggers one automatic retry at the same model level before cascading to the next model. Local reviews default to a 480-second request timeout and do not use a total deadline unless `POSTIL_LLM_TOTAL_TIMEOUT_SECS` is set. Exhausting a review or total deadline is terminal. Use the live benchmark harness before standardizing on a model: