fix(buzz-agent): escalate LLM timeouts per retry and log per-call latency (#5130)

Non-streaming LLM calls (`"stream": false`) through slow model/provider
combinations routinely take longer than the fixed
`BUZZ_AGENT_LLM_TIMEOUT_SECS` window (default 240 s) to return their
first response byte. The retry loop then re-ran the identical 240 s bet
three times, failed the turn, and the ACP harness requeued the whole
turn from scratch: agents spent 30+ minutes producing nothing while
every attempt died at the same wall. And because the LLM path only
logged WARN lines on failure, a healthy-but-slow call was
indistinguishable from a wedged one.

### Timeout handling

- **Per-attempt escalation**: the per-request budget doubles after each
timeout failure (`base × 2^n`, capped at `max(1200 s, base)` —
`escalated_timeout()` in `llm.rs`), shared by the main `post()` loop and
`openrouter_post()`. Non-timeout retryables (429/5xx/connect) do not
escalate. A call that needs six minutes now succeeds on a later attempt
instead of never.
- **Per-request total timeouts**: enforcement moved from the
client-level `read_timeout` to `RequestBuilder::timeout()` on each LLM
request, so escalated budgets aren't silently floored by the shared
client and each attempt's bound covers connect through body completion.
Timeout error messages were updated to match the new semantics and still
point at `BUZZ_AGENT_LLM_TIMEOUT_SECS`.

### Observability

- One INFO line per completed LLM call: model, provider, `duration_ms`,
`input_tokens`, `cached_input_tokens`, `output_tokens`. Slowness and
prompt-cache effectiveness are now visible in harness logs without
waiting for a failure, and `None` vs `0` token reports stay
distinguishable. Handoff summarization calls log the same line with
duration only.
- The agent main loop wraps the call in a `session_id` tracing span so
each line is attributable to a session.

---------

Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
This commit is contained in:
Will Pfleger
2026-08-07 11:45:39 -04:00
committed by GitHub
parent c293b3cd40
commit 346ae8cadc
2 changed files with 632 additions and 193 deletions
+3 -1
View File
@@ -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
File diff suppressed because it is too large Load Diff