From a84cc79b5fc2f6e9046cd11aa2064dd847e874e9 Mon Sep 17 00:00:00 2001 From: SmokeDev Date: Tue, 4 Aug 2026 08:06:53 -0700 Subject: [PATCH 1/3] fix(acp): name the method in request-timeout errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `AcpError::Timeout` carried only a `Duration`, so every timeout produced the same sentence regardless of which call actually hung: Request timeout — agent did not respond within 60s That is the message a user reports, and it is not enough to place the fault. Sessions are created lazily inside the prompt task, so a stalled `session/new` and a stalled `session/prompt` look identical from the outside — one of them is bounded at 60s and the other at 900s idle, and the operator cannot tell which they hit. Diagnosing #4098 needed a trace across two codebases and the timeout constants to work out that only `session/new` could produce that number. `send_request` already has the method in hand, and it is `&'static str` at every call site, so carrying it costs nothing: Request timeout — agent did not respond to session/new within 60s The two directly-constructed timeouts in `pool.rs` name theirs too (`session/set_model`, `session/set_config_option`), so no timeout in the crate is anonymous. Match sites become `Timeout { .. }`; nothing else changes, and the classification in `lib.rs` and `pool.rs` behaves exactly as before. Verified on Windows: `cargo check`, `cargo clippy --all-targets` (0 warnings) and `cargo fmt --check` clean for the crate. Not offering the crate's test suite as evidence: on this box it is non-deterministic against untouched main (consistent with #2492). Signed-off-by: SmokeDev --- crates/buzz-acp/src/acp.rs | 25 ++++++++++++++++++++----- crates/buzz-acp/src/lib.rs | 2 +- crates/buzz-acp/src/pool.rs | 14 ++++++++++---- 3 files changed, 31 insertions(+), 10 deletions(-) diff --git a/crates/buzz-acp/src/acp.rs b/crates/buzz-acp/src/acp.rs index 700d5e8dcf..ca0b8242bd 100644 --- a/crates/buzz-acp/src/acp.rs +++ b/crates/buzz-acp/src/acp.rs @@ -95,8 +95,15 @@ pub enum AcpError { #[error("Agent did not stop within {0:?} after cancellation")] CancelDrainTimeout(std::time::Duration), - #[error("Request timeout — agent did not respond within {0:?}")] - Timeout(std::time::Duration), + #[error("Request timeout — agent did not respond to {method} within {elapsed:?}")] + Timeout { + /// The JSON-RPC method that went unanswered. Without it a caller + /// cannot tell a slow `session/new` from a slow `session/prompt`, + /// and sessions are created lazily inside the prompt task — so the + /// two are indistinguishable from the outside (see #4098). + method: &'static str, + elapsed: std::time::Duration, + }, #[error("Write timeout — agent stopped reading stdin (blocked for {0:?})")] WriteTimeout(std::time::Duration), @@ -1075,7 +1082,7 @@ impl AcpClient { /// if they don't, the agent is likely stuck and we must not block forever. async fn send_request( &mut self, - method: &str, + method: &'static str, params: serde_json::Value, ) -> Result { let id = self.next_id; @@ -1096,12 +1103,20 @@ impl AcpClient { let timeout = Self::REQUEST_TIMEOUT; match tokio::time::timeout(timeout, self.write_ndjson(&msg)).await { Ok(result) => result?, - Err(_) => return Err(AcpError::Timeout(timeout)), + Err(_) => { + return Err(AcpError::Timeout { + method, + elapsed: timeout, + }) + } } match tokio::time::timeout(timeout, self.read_until_response(id)).await { Ok(result) => result, - Err(_) => Err(AcpError::Timeout(timeout)), + Err(_) => Err(AcpError::Timeout { + method, + elapsed: timeout, + }), } } diff --git a/crates/buzz-acp/src/lib.rs b/crates/buzz-acp/src/lib.rs index 811253e4ac..02879c867a 100644 --- a/crates/buzz-acp/src/lib.rs +++ b/crates/buzz-acp/src/lib.rs @@ -3470,7 +3470,7 @@ fn handle_prompt_result( e, acp::AcpError::Io(_) | acp::AcpError::WriteTimeout(_) - | acp::AcpError::Timeout(_) + | acp::AcpError::Timeout { .. } | acp::AcpError::Protocol(_) ); let error_code = match &e { diff --git a/crates/buzz-acp/src/pool.rs b/crates/buzz-acp/src/pool.rs index 64edf68ee2..01629736b7 100644 --- a/crates/buzz-acp/src/pool.rs +++ b/crates/buzz-acp/src/pool.rs @@ -1065,7 +1065,7 @@ async fn apply_model_switch( // so the caller can respawn the agent instead of reusing a poisoned one. Ok(Err(e @ AcpError::Io(_))) | Ok(Err(e @ AcpError::WriteTimeout(_))) - | Ok(Err(e @ AcpError::Timeout(_))) + | Ok(Err(e @ AcpError::Timeout { .. })) | Ok(Err(e @ AcpError::Protocol(_))) | Ok(Err(e @ AcpError::AgentExited)) => { tracing::error!( @@ -1088,7 +1088,10 @@ async fn apply_model_switch( target: "pool::model", "model set via {method_label} timed out ({MODEL_SWITCH_TIMEOUT:?}) — treating as fatal" ); - return Err(AcpError::Timeout(MODEL_SWITCH_TIMEOUT)); + return Err(AcpError::Timeout { + method: "session/set_model", + elapsed: MODEL_SWITCH_TIMEOUT, + }); } } Ok(()) @@ -1141,7 +1144,7 @@ async fn apply_permission_mode( // so the caller can respawn the agent. Ok(Err(e @ AcpError::Io(_))) | Ok(Err(e @ AcpError::WriteTimeout(_))) - | Ok(Err(e @ AcpError::Timeout(_))) + | Ok(Err(e @ AcpError::Timeout { .. })) | Ok(Err(e @ AcpError::Protocol(_))) | Ok(Err(e @ AcpError::AgentExited)) => { tracing::error!( @@ -1163,7 +1166,10 @@ async fn apply_permission_mode( target: "pool::permission", "permission mode set timed out ({PERMISSION_MODE_TIMEOUT:?}) — treating as fatal" ); - return Err(AcpError::Timeout(PERMISSION_MODE_TIMEOUT)); + return Err(AcpError::Timeout { + method: "session/set_config_option", + elapsed: PERMISSION_MODE_TIMEOUT, + }); } } Ok(()) From 404d6184db83d798f8fcc16219b2532fa2cd5114 Mon Sep 17 00:00:00 2001 From: SmokeDev Date: Tue, 4 Aug 2026 18:41:02 -0700 Subject: [PATCH 2/3] fix(acp): report the RPC the model switch actually sent on its outer timeout MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `apply_model_switch` serves both `ModelSwitchMethod` variants — ConfigOption sends `session/set_config_option`, SetModel sends `session/set_model` — but the outer-timeout branch hardcoded `session/set_model`, so a ConfigOption switch that blew the 5s budget would name a method it never sent. That is worse than the anonymous timeout this PR set out to fix: a wrong name sends whoever reads it looking in the wrong place. Derived from the variant instead. `method_label` beside it stays what it was — prose for humans, not an RPC name. Caught by the automated review on this PR. Signed-off-by: SmokeDev --- crates/buzz-acp/src/pool.rs | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/crates/buzz-acp/src/pool.rs b/crates/buzz-acp/src/pool.rs index 01629736b7..967df1085b 100644 --- a/crates/buzz-acp/src/pool.rs +++ b/crates/buzz-acp/src/pool.rs @@ -1037,6 +1037,13 @@ async fn apply_model_switch( } ModelSwitchMethod::SetModel { .. } => "set_model".to_string(), }; + // The RPC this switch actually sends, for the outer-timeout error below. + // `method_label` above is prose for humans; naming the wrong method in an + // error would be worse than naming none. + let rpc_method = match method { + ModelSwitchMethod::ConfigOption { .. } => "session/set_config_option", + ModelSwitchMethod::SetModel { .. } => "session/set_model", + }; let result = tokio::time::timeout(MODEL_SWITCH_TIMEOUT, async { match method { @@ -1089,7 +1096,7 @@ async fn apply_model_switch( "model set via {method_label} timed out ({MODEL_SWITCH_TIMEOUT:?}) — treating as fatal" ); return Err(AcpError::Timeout { - method: "session/set_model", + method: rpc_method, elapsed: MODEL_SWITCH_TIMEOUT, }); } From ceaaea8c4f35a9ab595106bf4ded391825e47a26 Mon Sep 17 00:00:00 2001 From: SmokeDev Date: Tue, 4 Aug 2026 18:53:24 -0700 Subject: [PATCH 3/3] test(acp): pin the model-switch RPC name to the request each variant sends CONTRIBUTING asks bug fixes to carry a regression test. This one is practical, so here it is rather than an explanation. The mapping moves into rpc_method_for() so it can be asserted directly. Extraction is part of the fix, not a drive-by: the defect was the dispatch and the error text disagreeing, and a free function is what lets a test hold them together as variants are added. Verified to FAIL against the pre-fix behaviour (both arms returning session/set_model) and pass with it. cargo fmt --all --check: clean. cargo clippy -p buzz-acp --all-targets -D warnings: clean. Signed-off-by: SmokeDev --- crates/buzz-acp/src/pool.rs | 42 ++++++++++++++++++++++++++++++------- 1 file changed, 35 insertions(+), 7 deletions(-) diff --git a/crates/buzz-acp/src/pool.rs b/crates/buzz-acp/src/pool.rs index 967df1085b..6bd184facf 100644 --- a/crates/buzz-acp/src/pool.rs +++ b/crates/buzz-acp/src/pool.rs @@ -1025,6 +1025,18 @@ async fn create_session_and_apply_model( /// with the agent's default model. This is intentionally non-fatal: a stale /// response from a timed-out request is safely ignored by `read_until_response` /// (non-matching JSON-RPC IDs are skipped). +/// The JSON-RPC method a given switch actually sends. +/// +/// Kept next to the dispatch it mirrors, and separate from `method_label`: +/// that one is prose for humans, this one names a wire method in an error a +/// caller may act on. Naming the wrong method is worse than naming none. +fn rpc_method_for(method: &ModelSwitchMethod) -> &'static str { + match method { + ModelSwitchMethod::ConfigOption { .. } => "session/set_config_option", + ModelSwitchMethod::SetModel { .. } => "session/set_model", + } +} + async fn apply_model_switch( acp: &mut AcpClient, session_id: &str, @@ -1037,13 +1049,7 @@ async fn apply_model_switch( } ModelSwitchMethod::SetModel { .. } => "set_model".to_string(), }; - // The RPC this switch actually sends, for the outer-timeout error below. - // `method_label` above is prose for humans; naming the wrong method in an - // error would be worse than naming none. - let rpc_method = match method { - ModelSwitchMethod::ConfigOption { .. } => "session/set_config_option", - ModelSwitchMethod::SetModel { .. } => "session/set_model", - }; + let rpc_method = rpc_method_for(method); let result = tokio::time::timeout(MODEL_SWITCH_TIMEOUT, async { match method { @@ -4002,6 +4008,28 @@ mod tests { use nostr::{EventBuilder, Keys, Kind, Tag, Timestamp}; use serde_json::json; + /// `apply_model_switch` serves BOTH variants but hardcoded + /// `session/set_model` in its outer-timeout error, so a ConfigOption + /// switch that blew the budget reported an RPC it never sent. The + /// dispatch and the error text have to agree for every variant, and only + /// a test keeps them agreeing as variants are added. + #[test] + fn rpc_method_matches_the_request_each_variant_sends() { + assert_eq!( + rpc_method_for(&ModelSwitchMethod::ConfigOption { + config_id: "model".to_string(), + option_value: "sonnet".to_string(), + }), + "session/set_config_option" + ); + assert_eq!( + rpc_method_for(&ModelSwitchMethod::SetModel { + model_id: "sonnet".to_string(), + }), + "session/set_model" + ); + } + // These pin the initial_message dispatch path (run_prompt_task, ~line 855): // a legacy agent WITH a base_prompt must get [Base] prepended to the user // message. This is the exact regression that shipped in the round-2 bug.