From ab153e13e14f871b5efe11a0cc68d29353040163 Mon Sep 17 00:00:00 2001 From: ijpq <509634578tk@gmail.com> Date: Wed, 5 Aug 2026 17:13:58 +0800 Subject: [PATCH 1/2] feat: log turn_in_flight gate rejections and in-turn prompt drops Three send_prompt*/fork_session sites reject a concurrent prompt with AcpError::TurnInProgress but emit nothing, so on a desktop run the rejection leaves no trace (the "logs didn't reveal anything" from #409). - debug! at the three gate sites (send_prompt_inner, send_prompt_linked_with_message_id, fork_session): an expected, user-driven queue-while-busy condition, carrying connection_id. - warn! tripwire before the mid-turn command handler's `_ => {}`: a Prompt reaching it means an ungated sender broke the gate invariant. Refs #409 Co-Authored-By: Claude Opus 4.8 --- src-tauri/src/acp/connection.rs | 14 ++++++++++++++ src-tauri/src/acp/manager.rs | 12 ++++++++++++ 2 files changed, 26 insertions(+) diff --git a/src-tauri/src/acp/connection.rs b/src-tauri/src/acp/connection.rs index abbcabf1e..ece29e960 100644 --- a/src-tauri/src/acp/connection.rs +++ b/src-tauri/src/acp/connection.rs @@ -6682,6 +6682,20 @@ async fn run_conversation_loop<'a>( disconnect_requested = true; break; } + Some(ConnectionCommand::Prompt { .. }) => { + // Tripwire, not a user-facing case. The + // `turn_in_flight` gate in `send_prompt_inner` + // rejects a second prompt BEFORE it is ever + // enqueued, so a `Prompt` reaching this mid-turn + // command handler means an ungated sender slipped + // past the gate (a broken invariant) — surface it + // at `warn` instead of letting the `_ => {}` below + // swallow it silently. + tracing::warn!( + connection_id = %conn_id, + "[ACP] in-turn Prompt DROPPED — the turn_in_flight gate should have rejected this" + ); + } _ => {} } } diff --git a/src-tauri/src/acp/manager.rs b/src-tauri/src/acp/manager.rs index 8cc2a67f3..31fb4bf69 100644 --- a/src-tauri/src/acp/manager.rs +++ b/src-tauri/src/acp/manager.rs @@ -730,6 +730,10 @@ impl ConnectionManager { { let mut s = state_arc.write().await; if s.turn_in_flight { + tracing::debug!( + connection_id = %conn_id, + "[ACP] prompt rejected: a turn is already in flight" + ); return Err(AcpError::TurnInProgress); } s.turn_in_flight = true; @@ -891,6 +895,10 @@ impl ConnectionManager { // InProgress or broadcasting a phantom user message. The frontend turns // this rejection into a queued message above the input box. if turn_in_flight { + tracing::debug!( + connection_id = %conn_id, + "[ACP] prompt rejected: a turn is already in flight" + ); return Err(AcpError::TurnInProgress); } @@ -1399,6 +1407,10 @@ impl ConnectionManager { // underneath us, but we never SET it: not setting the gate is precisely // why a dropped fork can't wedge the connection. if state_arc.read().await.turn_in_flight { + tracing::debug!( + connection_id = %conn_id, + "[ACP] fork rejected: a turn is already in flight" + ); return Err(AcpError::TurnInProgress); } From 0f1135c11e2cb111fe2073c4e739456efee6caf4 Mon Sep 17 00:00:00 2001 From: xintaofei Date: Wed, 5 Aug 2026 21:54:17 +0800 Subject: [PATCH 2/2] feat(acp): name each turn gate in its log and surface ext-notification drops The two turn_in_flight gate lines were byte-identical and share a module target with no file/line in the default format, so a reader could not tell which of the two checks bounced the prompt. Each now names its gate. maybe_emit_ext_notification is the silent fallback #409's second point was pointing at. All three of its drop paths now log at debug: an unhandled agent request, an unexpected response dispatch, and an ext notification whose method no mapper claims. The last is gated on is_known_ext_method so a _claude/sdkMessage that merely is not an API retry stays quiet -- that method arrives once per SDK message, and an unguarded line there would sit on a hot path. Refs #409 --- src-tauri/src/acp/connection.rs | 74 +++++++++++++++++++++++++++++++-- src-tauri/src/acp/manager.rs | 10 ++++- 2 files changed, 79 insertions(+), 5 deletions(-) diff --git a/src-tauri/src/acp/connection.rs b/src-tauri/src/acp/connection.rs index ece29e960..aad4f2b85 100644 --- a/src-tauri/src/acp/connection.rs +++ b/src-tauri/src/acp/connection.rs @@ -7865,8 +7865,12 @@ fn is_claude_api_retry_message(message: &serde_json::Value) -> bool { matches!(message_type, Some("system")) && matches!(message_subtype, Some("api_retry")) } +/// The JSON-RPC method claude-agent-acp uses to mirror raw SDK messages. Named +/// so `is_known_ext_method` and the mapper can't drift apart. +const CLAUDE_SDK_EXT_METHOD: &str = "_claude/sdkMessage"; + fn map_claude_sdk_ext_notification(notification: &UntypedMessage) -> Option { - if notification.method() != "_claude/sdkMessage" { + if notification.method() != CLAUDE_SDK_EXT_METHOD { return None; } @@ -7988,20 +7992,69 @@ fn grok_ext_notification_is_turn_output(dispatch: &Dispatch, agent_type: AgentTy } } +/// Whether codeg has a mapper for this ext-notification method. +/// +/// Used ONLY to keep the unrecognized-method log quiet about methods we do know +/// and merely declined to map this time. That distinction is the whole point: +/// `_claude/sdkMessage` arrives for every SDK message and only maps when the +/// payload is an API retry, so logging every unmapped one would put a line on a +/// per-message hot path — the shape that once grew a server's log file to 217GB. +/// +/// Forgetting to list a newly-mapped method here fails in the SAFE direction — +/// its unmapped payloads just get logged (noise, still visible). The dangerous +/// direction is the reverse: listing a method no mapper claims would silence +/// exactly the gap this log exists to expose. +fn is_known_ext_method(method: &str) -> bool { + method == CLAUDE_SDK_EXT_METHOD || GROK_EXT_UPDATE_METHODS.contains(&method) +} + +/// Last stop for a dispatch the typed `session/update` pipeline didn't claim. +/// +/// Every exit here DROPS the message, which is the pre-existing behavior and +/// stays that way — the change is that a drop is no longer invisible. All lines +/// are `debug!`: an agent is free to speak methods codeg doesn't implement, and +/// a per-message `warn!` on a chatty agent is how log storms start. async fn maybe_emit_ext_notification( state: &Arc>, emitter: &EventEmitter, agent_type: AgentType, dispatch: Dispatch, ) { - let Dispatch::Notification(notification) = dispatch else { - return; + let notification = match dispatch { + Dispatch::Notification(notification) => notification, + // An agent calling a client method codeg doesn't implement. The + // responder is dropped without a reply (as before), so the agent's + // request goes unanswered — worth seeing when triaging a stalled turn. + Dispatch::Request(request, _responder) => { + tracing::debug!( + method = %request.method(), + "[ACP] dropping unhandled agent request (no reply will be sent)" + ); + return; + } + // A response is normally consumed by the caller waiting on it, so one + // surfacing here is unexpected rather than routine. (It still carries a + // `ResponseRouter`, so "unroutable" would overstate it — the point is + // only that nothing on this path wants it.) + Dispatch::Response(..) => { + tracing::debug!("[ACP] dropping unexpected response dispatch"); + return; + } }; if let Some(event) = map_claude_sdk_ext_notification(¬ification) .or_else(|| map_grok_ext_notification(¬ification, agent_type)) { emit_with_state(state, emitter, event).await; + } else if !is_known_ext_method(notification.method()) { + // The gap #409's second point was reaching for: an agent emitting an ext + // method codeg has never heard of was previously indistinguishable from + // an agent saying nothing at all. + tracing::debug!( + method = %notification.method(), + agent = %agent_type, + "[ACP] ignoring unrecognized ext notification" + ); } } @@ -9346,6 +9399,21 @@ mod tests { } } + #[test] + fn is_known_ext_method_covers_every_mapped_method() { + // The anti-log-storm invariant: `_claude/sdkMessage` arrives for EVERY + // SDK message but only maps when it is an API retry, so it must be + // recognized here — otherwise each unmapped one logs a line on a + // per-message hot path. + assert!(is_known_ext_method(CLAUDE_SDK_EXT_METHOD)); + for method in GROK_EXT_UPDATE_METHODS { + assert!(is_known_ext_method(method), "{method} must be known"); + } + // A method no mapper claims is exactly what the log is for. + assert!(!is_known_ext_method("_vendor/somethingNew")); + assert!(!is_known_ext_method("session/update")); + } + #[test] fn map_claude_sdk_ext_notification_rejects_non_api_retry() { let non_retry = UntypedMessage::new( diff --git a/src-tauri/src/acp/manager.rs b/src-tauri/src/acp/manager.rs index 31fb4bf69..8b5b9ee59 100644 --- a/src-tauri/src/acp/manager.rs +++ b/src-tauri/src/acp/manager.rs @@ -730,9 +730,13 @@ impl ConnectionManager { { let mut s = state_arc.write().await; if s.turn_in_flight { + // Names the gate, not just the outcome: the linked path checks + // the same flag once before its side effects and again here, and + // the two lines share a module target with no file/line in the + // default format — identical text would be unattributable. tracing::debug!( connection_id = %conn_id, - "[ACP] prompt rejected: a turn is already in flight" + "[ACP] prompt rejected at the send gate: a turn is already in flight" ); return Err(AcpError::TurnInProgress); } @@ -895,9 +899,11 @@ impl ConnectionManager { // InProgress or broadcasting a phantom user message. The frontend turns // this rejection into a queued message above the input box. if turn_in_flight { + // Distinct from `send_prompt_inner`'s send-gate line so a log reader + // can tell which of the two checks bounced the prompt. tracing::debug!( connection_id = %conn_id, - "[ACP] prompt rejected: a turn is already in flight" + "[ACP] prompt rejected before admission: a turn is already in flight" ); return Err(AcpError::TurnInProgress); }