From ee0fd6aea8799c5d580371e4b505520105af745e Mon Sep 17 00:00:00 2001 From: Yogthos Date: Wed, 20 May 2026 21:48:31 -0400 Subject: [PATCH] fix(audit r7-followup): sanitize + dedup hook errors, partial-on-abort tool count + token parity MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TDD: tests first, all 6 new tests failed initially, then implemented. ## Round A — hook error sanitize + dedup Two bugs in PR #64's hook-error notification path: 1. Multi-line / tab-containing Janet errors broke the `level\tmsg\n` wire format. A `(error "trace\n at file:42")` produced multiple malformed notification entries (one per source line), the first with truncated content and the rest filtered out as malformed. drain_notifications splits raw on `\n` per entry and on first `\t` per level/msg — both control chars now sanitized in Janet before push. 2. A buggy `on-message-update` hook (fires ~every 16 streamed tokens) flooded the chat with thousands of identical "[plugin] hook X.Y errored: ..." banners during a single long response. Now deduped: two new Janet vars track the most-recent sanitized error msg + a consecutive-repeat count; identical errors just bump the count instead of pushing. On drain, any outstanding count is flushed as a "(repeated N times)" summary entry. Implementation: - `harness/sanitize-hook-err` (new) normalizes `\t` → space and `\n`/`\r\n` → ` | `. Distinct hook errors stay separate; only consecutive identical ones collapse. Wrote with explicit nested `string/replace-all` calls — Janet's `->` threading macro would pass the string in the wrong arg position (string/replace-all expects `(patt subst str)`). - `harness/push-hook-err` (new) does the dedup check using `harness-last-hook-err-msg` + `harness-last-hook-err-count` module-level vars. - `drain_notifications` flushes pending dedup count before reading the notif list so a 50× repeat shows up as a single "(repeated 50 times)" entry in the next drain. - The catch arm in `dispatch` calls these instead of appending directly. Wrapped in explicit `(do ...)` for Janet's single-form catch-body semantics. ## Round B — partial-on-abort trailer notes tool calls PR #65 saved the streamed assistant text on abort but didn't indicate that tool calls had also run in the same turn (whose results aren't in `response_buf` — only Token events accumulate there). The LLM on next turn would see the partial as a definitive "this was my reply" and could re-run side-effecting tools. `capture_partial_on_abort` now takes a `tool_calls_in_turn: u32` parameter. When non-zero, the trailer reads: [interrupted by user (Ctrl+C); 2 tool calls ran in this turn — results not preserved] Singular case ("1 tool call ran") uses the right noun. UI loop tracks `tool_calls_this_run: u32`, incremented on every `AgentEvent::ToolCall`, reset on `Done`/`Interjected`/both abort sites (since each marks the end of one agent run). ## Round C — token-accumulator parity on abort `Done` and `Interjected` branches both update `session.total_tokens` alongside the message add. The abort path didn't — made aborted turns look like zero-token contributions in the placeholder field. Fixed with an explicit `session.total_tokens.saturating_add(Session::estimate_tokens(&stashed))` inside `capture_partial_on_abort`. Both fields stay under the `TODO(cost-tracking)` comment but at least they're now internally consistent. ## Test plan - [x] 6 new tests (3 plugin dispatch + 3 capture_partial_on_abort + 2 updated existing tests with new signature). - [x] `cargo test --features plugin` -> 622 pass, 0 fail. - [x] `cargo build --all-features` -> compiles. ## Skipped (observational, not bugs) - #3 print/loop mode notifications never drained: print mode is non-interactive; tracing::warn (via `--verbose`) is the right channel. - #4 Janet `err` non-string-coerced: `(string ...)` calls Janet's `tostring` which handles any value type. Documented behavior. - #7 markdown rendering of `[interrupted by user (Ctrl+C)]`: not a link by pulldown-cmark's rules; visually acceptable inline. --- src/plugin/mod.rs | 159 ++++++++++++++++++++++++++++++++++++++++--- src/plugin/worker.rs | 51 ++++++++++++++ src/ui/mod.rs | 145 +++++++++++++++++++++++++++++++++++++-- 3 files changed, 341 insertions(+), 14 deletions(-) diff --git a/src/plugin/mod.rs b/src/plugin/mod.rs index 9fac1246..5cedc589 100644 --- a/src/plugin/mod.rs +++ b/src/plugin/mod.rs @@ -1337,6 +1337,121 @@ mod tests { assert!(out.contains(&"from-beta".to_string())); } + /// Multi-line and tab-containing Janet error messages must not + /// break the `level\tmsg\n` notification format. drain_notifications + /// splits on `\n` per entry and on the first `\t` per level/msg, + /// so embedded control chars would corrupt parsing — show up as + /// truncated entries and orphaned "malformed" lines. The catch + /// arm now sanitizes via `string/replace-all` before the push. + #[test] + fn dispatch_sanitizes_multi_line_and_tab_in_hook_errors() { + let path = tmpfile( + "multiline-err", + r#"(defn on-prompt [ctx] (error "line one\nline two\tline three"))"#, + ); + let mut mgr = PluginManager::try_new().unwrap(); + super::load_plugin(&mut mgr, &path).unwrap(); + let _ = std::fs::remove_file(&path); + + let _ = mgr.dispatch("on-prompt", "@{:prompt \"x\"}").unwrap(); + let pending = mgr.drain_notifications(); + + // Exactly one entry, even though the error contained both \n + // and \t. Without sanitization the multi-line error would + // either produce multiple malformed entries (one per source + // line) or split level/msg incorrectly at the embedded tab. + let err_entries: Vec<_> = pending.iter().filter(|(lvl, _)| lvl == "error").collect(); + assert_eq!(err_entries.len(), 1, "got entries: {:?}", pending); + let (_, msg) = err_entries[0]; + assert!(msg.contains("line one"), "msg missing 'line one': {msg}"); + assert!(msg.contains("line two"), "msg missing 'line two': {msg}"); + assert!( + msg.contains("line three"), + "msg missing 'line three': {msg}" + ); + // The msg field on the *Rust side* has already been split out + // of the wire format, so newlines/tabs inside it would only + // appear if our Janet sanitization missed them. Assert none. + assert!(!msg.contains('\n'), "msg leaked '\\n': {msg:?}"); + assert!(!msg.contains('\t'), "msg leaked '\\t': {msg:?}"); + } + + /// Consecutive identical hook errors (e.g. a buggy + /// on-message-update firing ~16x per response) must dedupe into a + /// single notification with a repeat-count suffix instead of + /// flooding the chat with 50+ identical banners. + #[test] + fn dispatch_dedupes_consecutive_identical_hook_errors() { + let path = tmpfile( + "repeat-err", + r#"(defn on-prompt [ctx] (error "always the same"))"#, + ); + let mut mgr = PluginManager::try_new().unwrap(); + super::load_plugin(&mut mgr, &path).unwrap(); + let _ = std::fs::remove_file(&path); + + for _ in 0..50 { + let _ = mgr.dispatch("on-prompt", "@{:prompt \"x\"}").unwrap(); + } + let pending = mgr.drain_notifications(); + + let err_entries: Vec<_> = pending.iter().filter(|(lvl, _)| lvl == "error").collect(); + // At most 2 entries (the first push + a "repeated N times" + // summary that flushes on drain). Definitely not 50. + assert!( + err_entries.len() <= 2, + "expected dedup (≤2 error entries); got {}: {:?}", + err_entries.len(), + pending, + ); + let combined: String = err_entries + .iter() + .map(|(l, m)| format!("{l}\t{m}")) + .collect::>() + .join(" | "); + assert!( + combined.contains("always the same"), + "msg dropped: {combined}", + ); + // The repeat-count summary must mention the number. + assert!( + combined.contains("repeated") && combined.contains("50"), + "expected repeat-count summary mentioning 50; got: {combined}", + ); + } + + /// Distinct hook errors must NOT be deduped — only consecutive + /// identical ones. A "B-error after A-error" should produce two + /// notifications, not one collapsed into the other. + #[test] + fn dispatch_distinct_hook_errors_are_not_deduped() { + let path_a = tmpfile( + "distinct-err-a", + r#"(defn on-prompt [ctx] (error "alpha error"))"#, + ); + let path_b = tmpfile( + "distinct-err-b", + r#"(defn on-response [ctx] (error "beta error"))"#, + ); + let mut mgr = PluginManager::try_new().unwrap(); + super::load_plugin(&mut mgr, &path_a).unwrap(); + super::load_plugin(&mut mgr, &path_b).unwrap(); + let _ = std::fs::remove_file(&path_a); + let _ = std::fs::remove_file(&path_b); + + let _ = mgr.dispatch("on-prompt", "@{:prompt \"x\"}").unwrap(); + let _ = mgr.dispatch("on-response", "@{:response \"y\"}").unwrap(); + let pending = mgr.drain_notifications(); + + let combined: String = pending + .iter() + .map(|(l, m)| format!("{l}\t{m}")) + .collect::>() + .join(" | "); + assert!(combined.contains("alpha"), "alpha missing: {combined}"); + assert!(combined.contains("beta"), "beta missing: {combined}"); + } + /// A hook that throws is caught: dispatch continues (no panic, /// no propagated error to the caller), `nil` is the effective /// return value (filtered out of the results vec), AND the @@ -1712,16 +1827,17 @@ impl PluginManager { let code = format!( r#"(try (do (def ctx {ctx}) ({fname} ctx)) ([err fib] - (set harness-notif-list - (string harness-notif-list - "error\t[plugin] hook " - {hook_lit} - "." - {fname_lit} - " errored: " - err - "\n")) - (string "DIRGE_HOOK_ERR:" err)))"#, + (do + (def sanitized + (harness/sanitize-hook-err + (string "[plugin] hook " + {hook_lit} + "." + {fname_lit} + " errored: " + err))) + (harness/push-hook-err sanitized) + (string "DIRGE_HOOK_ERR:" err))))"#, ctx = context_janet, fname = name, hook_lit = format!("\"{}\"", escape_janet_string(hook)), @@ -1922,6 +2038,29 @@ impl PluginManager { /// renders entries as colored chat lines. Returns an empty Vec when /// no plugin has posted anything. pub fn drain_notifications(&mut self) -> Vec<(String, String)> { + // Flush any pending hook-error dedup count BEFORE reading + // `harness-notif-list`. If a hook errored 50 times in a row, + // the first error is already on the list and the next 49 + // got coalesced into `harness-last-hook-err-count`. The + // flush appends a single "(repeated 49 times)" entry so the + // count shows up in the next drain instead of being lost. + // Resets the dedup slots regardless so a future drain + // starts fresh. + let _ = self.worker.eval( + r#"(do + (when (and harness-last-hook-err-msg + (> harness-last-hook-err-count 1)) + (set harness-notif-list + (string harness-notif-list + "error\t" + harness-last-hook-err-msg + " (repeated " + harness-last-hook-err-count + " times)\n"))) + (set harness-last-hook-err-msg nil) + (set harness-last-hook-err-count 0))"#, + ); + let raw = match self.worker.eval("harness-notif-list") { Ok(s) => s, Err(_) => return Vec::new(), diff --git a/src/plugin/worker.rs b/src/plugin/worker.rs index d0ba7b9b..9d810a4c 100644 --- a/src/plugin/worker.rs +++ b/src/plugin/worker.rs @@ -112,6 +112,57 @@ const HARNESS_INIT: &str = r#" (set harness-notif-list (string harness-notif-list lvl "\t" msg "\n"))))) +# Hook-error dedup slots. `harness-last-hook-err-msg` is the most +# recently pushed sanitized hook-error message; `harness-last-hook-err-count` +# is how many consecutive identical errors followed it. When a +# DIFFERENT error arrives (or any other notification fires), the +# count is flushed as a "(repeated N times)" entry. Drained alongside +# the regular notif list. See `harness/push-hook-err` below + the +# Rust-side dispatch wrapper in `plugin/mod.rs::dispatch`. +(var harness-last-hook-err-msg nil) +(var harness-last-hook-err-count 0) + +# Sanitize a hook-error message for the `level\tmsg\n` wire format. +# Embedded tabs become spaces (so they don't get parsed as a second +# `level` field) and newlines become ` | ` (so a multi-line Janet +# stack trace stays on one notification entry). +# +# `string/replace-all` takes args as (patt subst str), so threading +# with `->` (first-position) would pass the wrong arg as the +# subject. Explicit nesting from inside out is the safest spelling. +(defn harness/sanitize-hook-err [s] + (string/replace-all + "\n" " | " + (string/replace-all + "\r\n" " | " + (string/replace-all "\t" " " (string s))))) + +# Push a hook error onto the notif list, deduplicating consecutive +# identical messages. The catch arm in dispatch calls this rather +# than appending directly so a buggy on-message-update hook can't +# flood the chat with thousands of identical banners. +(defn harness/push-hook-err [sanitized-msg] + (if (= sanitized-msg harness-last-hook-err-msg) + # Same as last — increment in place; do not push. + (set harness-last-hook-err-count (+ harness-last-hook-err-count 1)) + # Different message (or first one). If the previous one had + # been repeated, flush its summary now; then push the new msg + # and reset the dedup state. + (do + (when (and harness-last-hook-err-msg + (> harness-last-hook-err-count 1)) + (set harness-notif-list + (string harness-notif-list + "error\t" + harness-last-hook-err-msg + " (repeated " + harness-last-hook-err-count + " times)\n"))) + (set harness-notif-list + (string harness-notif-list "error\t" sanitized-msg "\n")) + (set harness-last-hook-err-msg sanitized-msg) + (set harness-last-hook-err-count 1)))) + # Plugin entries on the session timeline. Plugins call # (harness/append-entry type data &opt display) to record # bookmarks, telemetry, or custom state that should survive diff --git a/src/ui/mod.rs b/src/ui/mod.rs index d65b6c8b..5c5e1068 100644 --- a/src/ui/mod.rs +++ b/src/ui/mod.rs @@ -84,6 +84,14 @@ fn with_queue(s: String, n: usize) -> String { /// when a partial was actually stashed; `false` when nothing had /// streamed yet (no-op). /// +/// `tool_calls_in_turn` is the count of `AgentEvent::ToolCall` events +/// the UI saw during the aborted turn. When non-zero, the trailer +/// notes that tool calls ran but their results are NOT in the +/// preserved text (since only Token events accumulate into +/// `response_buf`). Without this hint, the next turn's LLM context +/// would treat the partial as a complete reply and could re-run +/// side-effecting tools. +/// /// Mirrors opencode's `finalizeInterruptedAssistant` in /// `packages/opencode/src/session/prompt.ts` — the streamed parts /// are already on-screen, so the partial is preserved by virtue of @@ -95,14 +103,36 @@ fn capture_partial_on_abort( response_buf: &mut String, session: &mut crate::session::Session, why: &str, + tool_calls_in_turn: u32, ) -> bool { let trimmed = response_buf.trim_end(); if trimmed.is_empty() { response_buf.clear(); return false; } - let stashed = format!("{}\n\n[interrupted by user ({})]", trimmed, why,); + let trailer = if tool_calls_in_turn > 0 { + let noun = if tool_calls_in_turn == 1 { + "tool call ran" + } else { + "tool calls ran" + }; + format!( + "[interrupted by user ({}); {} {} in this turn — results not preserved]", + why, tool_calls_in_turn, noun, + ) + } else { + format!("[interrupted by user ({})]", why) + }; + let stashed = format!("{}\n\n{}", trimmed, trailer); + // Capture the message's token estimate before add_message so we + // can also bump `total_tokens` in lockstep with + // `total_estimated_tokens` — matches the Done / Interjected + // branches which both update total_tokens (a TODO(cost-tracking) + // placeholder; kept consistent so the abort case doesn't look + // like a zero-token turn). + let est = crate::session::Session::estimate_tokens(&stashed); session.add_message(crate::session::MessageRole::Assistant, &stashed); + session.total_tokens = session.total_tokens.saturating_add(est); response_buf.clear(); true } @@ -418,6 +448,12 @@ pub async fn run_interactive( let mut agent_interject: Option> = None; let mut agent_line_started = false; let mut response_buf = String::new(); + // Count of `AgentEvent::ToolCall` events observed during the + // current run. Used by `capture_partial_on_abort` so the + // saved partial's trailer can warn the LLM that tool calls + // ran but their results aren't in the preserved text. Reset + // when a new agent run starts (alongside response_buf clear). + let mut tool_calls_this_run: u32 = 0; // Per-turn streaming state for the plugin hooks. The batcher // collects tokens since the last `on-message-update` dispatch so // we don't round-trip into Janet for every single token; the @@ -768,7 +804,12 @@ pub async fn run_interactive( &mut response_buf, session, "Ctrl+C", + tool_calls_this_run, ); + // Whether or not we stashed, the run + // is over — reset the counter so a + // subsequent run starts at zero. + tool_calls_this_run = 0; let dropped = interjection_queue.len(); interjection_queue.clear(); let mut msg = String::from("interrupted"); @@ -940,7 +981,9 @@ pub async fn run_interactive( &mut response_buf, session, "Esc", + tool_calls_this_run, ); + tool_calls_this_run = 0; let msg = if stashed { "interrupted (Esc) — partial reply preserved in session" } else { @@ -1511,6 +1554,12 @@ pub async fn run_interactive( } AgentEvent::ToolCall { name, args } => { was_reasoning = false; + // Track for the abort-trailer warning: when + // the user later hits Ctrl+C / Esc, the + // saved partial reply notes how many tool + // calls ran (and didn't have their results + // preserved in the message text). + tool_calls_this_run = tool_calls_this_run.saturating_add(1); renderer.set_avatar_state(avatar::AvatarState::from_tool_name(&name)); // If a previous tool's chamber never closed // (errored without a ToolResult, etc.), close @@ -1738,6 +1787,11 @@ pub async fn run_interactive( // the wiring is in place when real values arrive. session.total_tokens = session.total_tokens.saturating_add(tokens); session.total_cost += cost; + // Run ended cleanly — reset the per-run tool- + // call counter so the next user submission + // starts at zero. Mirrored in the Interjected + // branch + both abort paths below. + tool_calls_this_run = 0; agent_line_started = false; response_buf.clear(); response_start_line = None; @@ -2006,6 +2060,10 @@ pub async fn run_interactive( // provider usage. Wire after rig usage plumbing. session.total_tokens = session.total_tokens.saturating_add(tokens); } + // Run ended (interjection-style) — reset the + // per-run tool-call counter alongside the + // other per-run state. + tool_calls_this_run = 0; agent_line_started = false; response_buf.clear(); response_start_line = None; @@ -3163,7 +3221,7 @@ mod tests { let mut session = crate::session::Session::new("openrouter", "test-model", 100_000); let baseline = session.messages.len(); let mut buf = String::from("I was about to explain that"); - let stashed = capture_partial_on_abort(&mut buf, &mut session, "Ctrl+C"); + let stashed = capture_partial_on_abort(&mut buf, &mut session, "Ctrl+C", 0); assert!(stashed); assert_eq!(session.messages.len(), baseline + 1); let last = session.messages.last().unwrap(); @@ -3189,7 +3247,7 @@ mod tests { let mut session = crate::session::Session::new("openrouter", "test-model", 100_000); let baseline = session.messages.len(); let mut buf = String::new(); - let stashed = capture_partial_on_abort(&mut buf, &mut session, "Ctrl+C"); + let stashed = capture_partial_on_abort(&mut buf, &mut session, "Ctrl+C", 0); assert!(!stashed); assert_eq!(session.messages.len(), baseline); } @@ -3201,11 +3259,90 @@ mod tests { let mut session = crate::session::Session::new("openrouter", "test-model", 100_000); let baseline = session.messages.len(); let mut buf = String::from(" \n\n\t "); - let stashed = capture_partial_on_abort(&mut buf, &mut session, "Esc"); + let stashed = capture_partial_on_abort(&mut buf, &mut session, "Esc", 0); assert!(!stashed); assert_eq!(session.messages.len(), baseline); } + // When tool calls ran in the same turn as the abort, the trailer + // must say so. The agent's preserved text only covers what was + // streamed via `AgentEvent::Token`; tool calls + results emitted + // separately are NOT in `response_buf`. Without this hint the + // next turn's LLM would see the partial as a definitive "this + // was the assistant's response" and could re-run side-effecting + // tool calls. + #[test] + fn capture_partial_on_abort_trailer_notes_tool_calls() { + let mut session = crate::session::Session::new("openrouter", "test-model", 100_000); + let mut buf = String::from("I deleted the file"); + let stashed = capture_partial_on_abort(&mut buf, &mut session, "Ctrl+C", 2); + assert!(stashed); + let content = &session.messages.last().unwrap().content; + assert!( + content.contains("I deleted the file"), + "partial text dropped: {content:?}", + ); + assert!( + content.contains("[interrupted by user (Ctrl+C);"), + "trailer prefix changed: {content:?}", + ); + assert!( + content.contains("2 tool call"), + "trailer must mention tool call count: {content:?}", + ); + assert!( + content.contains("not preserved"), + "trailer must warn that tool calls were not preserved: {content:?}", + ); + } + + // Single tool call uses singular phrasing — "1 tool call ran" not + // "1 tool calls ran". Tiny but the LLM is reading this verbatim. + #[test] + fn capture_partial_on_abort_trailer_handles_singular_tool_call() { + let mut session = crate::session::Session::new("openrouter", "test-model", 100_000); + let mut buf = String::from("Running tests now"); + capture_partial_on_abort(&mut buf, &mut session, "Esc", 1); + let content = &session.messages.last().unwrap().content; + assert!( + content.contains("1 tool call ran"), + "expected singular phrasing for 1 tool call: {content:?}", + ); + assert!( + !content.contains("1 tool calls ran"), + "leaked plural for singular case: {content:?}", + ); + } + + // The token accumulator on the abort path keeps `total_tokens` + // in sync with `total_estimated_tokens`. Both fields are + // TODO(cost-tracking) placeholders today but the inconsistency + // between Done/Interjected (which both update total_tokens) and + // abort (which didn't) made the abort case look like the agent + // produced zero tokens that turn. + #[test] + fn capture_partial_on_abort_keeps_total_tokens_in_sync() { + let mut session = crate::session::Session::new("openrouter", "test-model", 100_000); + let baseline_total = session.total_tokens; + let baseline_est = session.total_estimated_tokens; + let mut buf = String::from( + "A reasonably long partial response that should produce a non-zero token estimate.", + ); + capture_partial_on_abort(&mut buf, &mut session, "Ctrl+C", 0); + // Both fields advanced by the same amount (the stashed + // message's estimated_tokens). Without the parity fix, only + // total_estimated_tokens moved. + assert!( + session.total_estimated_tokens > baseline_est, + "total_estimated_tokens should advance on stash", + ); + assert_eq!( + session.total_tokens.saturating_sub(baseline_total), + session.total_estimated_tokens.saturating_sub(baseline_est), + "total_tokens must advance in lockstep with total_estimated_tokens", + ); + } + // Regression H1: lifecycle line for a failed task previously embedded the // raw error string. Renderer.write_line splits on '\n', so a multi-line // error broke the line layout (color reset, closing ']' on its own row).