Skip to content

fix(buzz-agent): classify read timeouts distinctly in LLM error messages - #4959

Open
wpfleger96 wants to merge 5 commits into
mainfrom
duncan/llm-timeout-classification
Open

fix(buzz-agent): classify read timeouts distinctly in LLM error messages#4959
wpfleger96 wants to merge 5 commits into
mainfrom
duncan/llm-timeout-classification

Conversation

@wpfleger96

@wpfleger96 wpfleger96 commented Aug 5, 2026

Copy link
Copy Markdown
Member

Problem

When buzz-agent exhausts retries on a stalled LLM call, the error message reads:

transport: error sending request for url (...) (cumulative 721s, 3 attempts)

That text is reqwest's generic pre-response failure string — identical whether the cause is a TLS abort, a reset connection, or a read_timeout fire. An operator reading the log cannot tell whether something broke or whether the LLM generation legitimately took longer than the configured timeout.

Root cause (probe-confirmed)

A live probe against goose-claude-fable-5 with a 900s client timeout completed in 370s — well past the default BUZZ_AGENT_LLM_TIMEOUT_SECS=240. Extended-thinking models emit zero bytes on non-streaming calls until generation is complete, so reqwest's read_timeout fires on byte-silence regardless of whether the server is healthy. The 46× exact-721s stall signatures in production logs (3 × 240s + backoff) are deterministic self-inflicted timeouts, not network faults.

Fix

Pure classifier over {is_connect, llm_timeout, phase}

A new timeout_message(is_connect: bool, llm_timeout: Duration, phase: TimeoutPhase) pure function produces factual messages with the configured duration value embedded verbatim. Two thin wrappers (classify_transport_error, classify_body_read_error) extract the reqwest flags and delegate. The duration reaches the classifiers through a new read_timeout: Duration parameter on post() and openrouter_post(); callers pass cfg.llm_timeout.

Messages emitted

Case Message
Connect-phase timeout (is_connect && is_timeout) connect timeout: no connection established within 10s
Transport read-timeout read timeout: no response bytes received within 240s (consider raising BUZZ_AGENT_LLM_TIMEOUT_SECS)
Body-read timeout read timeout: no further response bytes received within 240s (consider raising BUZZ_AGENT_LLM_TIMEOUT_SECS)
Non-timeout transport: {reqwest text} / body read: {reqwest text} (unchanged)

LLM_CONNECT_TIMEOUT is now a named const (was inline from_secs(10)).

Out of scope by explicit decision: streaming support, changes to MAX_RETRIES or backoff.

Files changed

  • crates/buzz-agent/src/llm.rstimeout_message pure fn + TimeoutPhase enum + LLM_CONNECT_TIMEOUT const; two classifier wrappers updated; post() and openrouter_post() gain read_timeout param; tests replaced.

Tests

cargo test -p buzz-agent: 397 passed, 0 failed at 294ce5897.

Pure-function tests (no network):

  • timeout_message_connect_true_shows_connect_timeoutis_connect=true → connect-flavored text with 10s value; both phases checked
  • timeout_message_transport_phase_shows_read_timeout_and_duration — transport phase includes 240s and config knob
  • timeout_message_body_read_phase_says_no_further_bytes_and_duration — body phase says "no further", shows 300s
  • timeout_message_duration_is_not_hardcoded — 600s supplied → 600s in output, not 240s

Loopback reqwest integration tests:

  • classify_transport_error_read_timeout_is_loopback_verified — TCP connect succeeds, server sends no bytes; verifies reqwest sets is_timeout && !is_connect and message contains 50ms value
  • classify_transport_error_non_timeout_preserves_reqwest_text — controlled accept-then-close on an owned loopback listener → non-timeout error; asserts exact transport: {err} output equality
  • classify_body_read_error_timeout_says_no_further_bytes — loopback server sends headers + 4 bytes of a declared-1024-byte body, then holds; verifies is_timeout, "no further", 100ms value, config knob

No test performs egress beyond loopback (127.0.0.1). The TEST-NET-3 dial is deleted.

@wpfleger96
wpfleger96 requested a review from a team as a code owner August 5, 2026 20:48
Duncan and others added 2 commits August 5, 2026 17:04
reqwest's Display for a read_timeout fire is the opaque
'error sending request for url (...)' — identical to every other
pre-response transport failure. An operator reading a log line like

  transport: error sending request for url (...) (cumulative 721s, 3 attempts)

cannot tell whether the call hit a network fault or whether the LLM
generation legitimately took longer than BUZZ_AGENT_LLM_TIMEOUT_SECS
(default 240s). The latter is common on extended-thinking models
(fable-5, opus-5) whose non-streaming turns can exceed 240s — confirmed
by a live probe showing 370s wall time for a max-effort generation.

Add classify_transport_error() and classify_body_read_error() that check
reqwest::Error::is_timeout() and emit a message naming the actual cause
and the config knob to raise (BUZZ_AGENT_LLM_TIMEOUT_SECS). Non-timeout
errors fall through to the original format strings so no existing
diagnostic text is lost. Add is_timeout field to retry warn! events for
log-based filtering. Tests use real loopback sockets to produce genuine
reqwest::Error values with is_timeout() == true/false.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
…out guard

Read timeouts now emit factual messages — no cause speculation — and
connect timeouts are guarded with is_connect() so they produce
connect-flavored text instead of the read-timeout message.

Previously classify_transport_error said 'likely long generation/thinking'
for any is_timeout() error. Two defects:
- is_connect() && is_timeout() (connect-phase timeout) would produce the
  read-timeout text with wrong guidance.
- A mid-flight network partition is indistinguishable from a slow
  generation on the client side; asserting a cause is misleading.

New messages:
- connect timeout: 'no connection established within the configured connect timeout'
- read timeout:    'no response bytes received within the configured read timeout
                   (consider raising BUZZ_AGENT_LLM_TIMEOUT_SECS)'
- body-read timeout: 'no further response bytes received ...' (headers/partial
                     body already arrived — 'no response bytes' was wrong there too)

Tests: renamed timeout test to _read_timeout_, added is_connect precondition
assertion, added connect-timeout branch test, added no-speculation assertion.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
@wpfleger96
wpfleger96 force-pushed the duncan/llm-timeout-classification branch from 8bcb980 to 216b898 Compare August 5, 2026 21:13
Duncan and others added 3 commits August 5, 2026 17:50
…fier, body-read coverage

Addresses four Thufir findings on #4959:

1. Duration now appears in every timeout message. A new pure function
   timeout_message(is_connect, llm_timeout, phase) takes the configured
   Duration explicitly and renders it verbatim. Connect-phase timeouts
   show LLM_CONNECT_TIMEOUT (10s); read-phase timeouts show the caller-
   supplied llm_timeout (BUZZ_AGENT_LLM_TIMEOUT_SECS, default 240s).
   Both post() and openrouter_post() now accept read_timeout: Duration
   and thread it to the classifiers; callers pass cfg.llm_timeout.
   LLM_CONNECT_TIMEOUT is now a named constant (was inline from_secs(10)).

2. Flag-precedence logic is now a pure function. timeout_message takes
   (is_connect: bool, llm_timeout, phase) rather than &reqwest::Error,
   so every branch (connect-timeout, transport read-timeout, body-read
   timeout) is directly testable without network I/O. Four pure #[test]
   cases cover all branches plus a hardcode-guard for the duration value.
   The TEST-NET-3 (203.0.113.1) egress test is deleted entirely.

3. Body-read timeout path now has a timeout test. A loopback server
   sends HTTP 200 with Content-Length:1024 but only 4 bytes of body, then
   holds the connection open; the client times out on the second chunk.
   Test asserts 'no further response bytes', the 100ms configured value,
   and the BUZZ_AGENT_LLM_TIMEOUT_SECS knob.

4. Doc comment corrected: 'at least one body chunk' -> 'headers and
   possibly body bytes arrived' (a chunk() timeout can fire before the
   first body chunk).

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
… loopback

The non-timeout classifier test dialled 127.0.0.1:1 relying on the
invariant that port 1 is never bound. A privileged or containerised
process can bind port 1, making expect_err() host-dependent.

Replace with bind-127.0.0.1:0, capture the ephemeral address, drop
the listener, then dial the released port. The kernel produces a
deterministic connection-refused with no fixed-port assumption and
zero network egress beyond loopback.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
bind-then-drop releases the ephemeral port before the dial, leaving a
TOCTOU window where any concurrent binder can claim it. Retain the
listener for the test's lifetime and spawn a task that accepts exactly
one connection and immediately drops the socket. The test holds exclusive
ownership of the address throughout, producing a deterministic
request-class error (not is_timeout()) with no released-port race.

Also strengthen the assertion from starts_with("transport: ") to exact
equality against format!("transport: {err}"), matching the test name's
promise of exact text preservation.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant