diff --git a/CHANGELOG.md b/CHANGELOG.md index ab34bb4..c42cb69 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,26 @@ adheres to [Semantic Versioning](https://semver.org/). ### Changed +- **Fixed: summarization retries panicked in debug builds, silently.** + `RetryConfig::delay_for_attempt` documents a 1-indexed attempt and computes + `attempt - 1`; `llm_compaction.rs` passed the raw `0..=max_retries` loop + variable, so the first retry underflowed `usize`. `agent_loop.rs` increments + before calling and was correct — this was confined to compaction. + + It landed on a **detached** task, so nothing surfaced: the summarization + simply vanished, no briefing arrived, and compaction fell back + deterministically. That is one of the behaviours + [#150](https://github.com/yologdev/yoagent/issues/150) was filed about. + + `delay_for_attempt` now uses `saturating_sub`, so a caller that misses the + 1-indexed contract loses the backoff rather than the task. + + `provider_failure_falls_back_deterministically` had been passing *because* of + this panic: its `FailingProvider` returns a retryable error, and the instant + death released the in-flight slot inside the test's 100ms window. With + retries working the first backoff is ~1s, so the test now configures no + retries — it is about the drop guard, not about backoff timing. + - **`LlmCompaction` says so when briefings keep losing the race** ([#150](https://github.com/yologdev/yoagent/issues/150)). A session whose compactions all take the deterministic path gets `DefaultCompaction`'s diff --git a/src/llm_compaction.rs b/src/llm_compaction.rs index 41188cf..4f6daf8 100644 --- a/src/llm_compaction.rs +++ b/src/llm_compaction.rs @@ -1083,7 +1083,12 @@ async fn summarize( if e.is_retryable() && attempt < retry.max_retries { let delay = e .retry_after() - .unwrap_or_else(|| retry.delay_for_attempt(attempt)); + // `attempt` is 0-indexed here (`0..=max_retries`) but + // `delay_for_attempt` documents 1-indexed and computes + // `attempt - 1`, so passing it raw underflowed on the + // first retry. `agent_loop.rs` increments before + // calling; this did not. + .unwrap_or_else(|| retry.delay_for_attempt(attempt + 1)); tracing::debug!("llm compaction: {e}, retrying in {delay:?}"); tokio::time::sleep(delay).await; continue; @@ -1094,7 +1099,7 @@ async fn summarize( Ok(Ok(message)) => return accept_summary(message), } if attempt < retry.max_retries { - tokio::time::sleep(retry.delay_for_attempt(attempt)).await; + tokio::time::sleep(retry.delay_for_attempt(attempt + 1)).await; } } None @@ -2179,11 +2184,65 @@ mod tests { } } + /// Real fallbacks through `compact()` feed the streak and trip the warning. + /// + /// Lives here, in `mod tests`, because the helpers do. The sibling + /// `losing_race_warning` module calls `warn_losing_race_once` directly, so + /// deleting its only call site in `compact` left every one of those tests + /// green while disconnecting the feature entirely — the counter would never + /// move for any real user. + #[tokio::test(flavor = "multi_thread")] + async fn compact_counts_real_fallbacks_and_warns_on_the_streak() { + let strategy = LlmCompaction::from_provider(Arc::new(FailingProvider), ModelConfig::mock()) + .with_trigger_ratio(0.1) + .with_retain_tail_tokens(200) + .with_retry_config(crate::retry::RetryConfig::none()); + let cfg = config(2_000); + + // The summarizer always fails, so no briefing is ever ready and every + // compaction takes the deterministic path — the condition the warning + // exists to report. + for expected in 1..FALLBACKS_BEFORE_WARNING { + let _ = strategy.compact(history(30, 400), &cfg); + // Let the spawned request fail and release the slot, so the next + // compaction arms again rather than seeing a busy phase. + tokio::time::sleep(std::time::Duration::from_millis(30)).await; + assert_eq!( + lock(&strategy.state).fallbacks, + expected, + "each deterministic compaction must advance the streak" + ); + assert!( + !lock(&strategy.state).warned.losing_race, + "{expected} of {FALLBACKS_BEFORE_WARNING} is not yet a streak" + ); + } + + let _ = strategy.compact(history(30, 400), &cfg); + tokio::time::sleep(std::time::Duration::from_millis(30)).await; + assert!( + lock(&strategy.state).warned.losing_race, + "{FALLBACKS_BEFORE_WARNING} consecutive real fallbacks must trip the warning" + ); + } + #[tokio::test(flavor = "multi_thread")] async fn provider_failure_falls_back_deterministically() { + // No retries, so the failure is immediate and the 100ms below actually + // bounds it. This test is about the drop guard releasing the slot, not + // about backoff timing. + // + // It previously passed for the wrong reason: `FailingProvider` returns + // a *retryable* error, and `delay_for_attempt` was called 0-indexed + // against its documented 1-indexed contract, so the first retry + // panicked on `usize` underflow. The task died instantly, the guard + // dropped, and the assertion held — on a debug-only panic on a detached + // task. With the indexing fixed the first backoff is ~1s and the slot + // is legitimately still in flight at 100ms. let strategy = LlmCompaction::from_provider(Arc::new(FailingProvider), ModelConfig::mock()) .with_trigger_ratio(0.1) - .with_retain_tail_tokens(200); + .with_retain_tail_tokens(200) + .with_retry_config(crate::retry::RetryConfig::none()); let messages = history(30, 400); let cfg = config(2_000); diff --git a/src/retry.rs b/src/retry.rs index 784ba70..3dc3fa4 100644 --- a/src/retry.rs +++ b/src/retry.rs @@ -43,8 +43,16 @@ impl RetryConfig { /// Calculate the delay for a given attempt (1-indexed). /// Uses exponential backoff with ±20% jitter. pub fn delay_for_attempt(&self, attempt: usize) -> Duration { - let base_ms = - self.initial_delay_ms as f64 * self.backoff_multiplier.powi((attempt - 1) as i32); + // `saturating_sub`, not `attempt - 1`: this is a public method whose + // 1-indexed contract is easy to miss, and `usize` underflow panics in + // debug. `llm_compaction.rs` passed it 0-indexed and died on the first + // retry — on a *detached* task, so the summarization simply vanished + // and compaction fell back deterministically with nothing logged. + // A misuse should cost the backoff, not the task. + let base_ms = self.initial_delay_ms as f64 + * self + .backoff_multiplier + .powi(attempt.saturating_sub(1) as i32); let capped_ms = base_ms.min(self.max_delay_ms as f64); // Jitter: ±20% (multiply by 0.8–1.2) @@ -83,3 +91,51 @@ pub(crate) fn log_retry(attempt: usize, max: usize, delay: &Duration, error: &Pr error ); } + +#[cfg(test)] +mod attempt_indexing { + use super::RetryConfig; + + /// A zero attempt must not panic. + /// + /// `delay_for_attempt` documents 1-indexed and computed `attempt - 1`, so a + /// 0-indexed caller hit `usize` underflow — a debug panic. `llm_compaction` + /// did exactly that, and because the retry runs on a detached task the + /// panic was invisible: the summarization vanished and compaction fell back + /// deterministically, which is one of the behaviours #150 was filed about. + #[test] + fn a_zero_attempt_does_not_panic() { + let cfg = RetryConfig { + initial_delay_ms: 1000, + backoff_multiplier: 2.0, + max_delay_ms: 60_000, + ..RetryConfig::default() + }; + // Reaching this line at all is the point — the old code panicked here. + let zero = cfg.delay_for_attempt(0).as_millis(); + // Jitter is +/-20% of the base 1000ms, so 0 degrades into the same band + // as attempt 1 rather than to something wild. + assert!( + (800..=1200).contains(&zero), + "attempt 0 must degrade to the base delay, got {zero}ms" + ); + } + + /// Backoff still grows for the documented 1-indexed usage. + #[test] + fn backoff_grows_with_the_attempt_number() { + let cfg = RetryConfig { + initial_delay_ms: 1000, + backoff_multiplier: 2.0, + max_delay_ms: 60_000, + ..RetryConfig::default() + }; + // Jitter is +/-20%, so compare with margin rather than exactly. + let first = cfg.delay_for_attempt(1).as_millis(); + let third = cfg.delay_for_attempt(3).as_millis(); + assert!( + third > first * 2, + "attempt 3 must back off well beyond attempt 1, got {first}ms then {third}ms" + ); + } +}