From 54e9206f0bb45d9aa576c7085e4fc42b5c7547be Mon Sep 17 00:00:00 2001 From: Illia Polosukhin Date: Fri, 13 Feb 2026 15:24:07 -0800 Subject: [PATCH] feat: Move debug log truncation from agent loop to REPL channel (#65) * feat: Move debug log truncation from agent loop to REPL channel Full tool output now flows through StatusUpdate so the web gateway gets untruncated content. The REPL channel truncates at display time (200 chars for tool results, thinking, and status messages). Co-Authored-By: Claude Opus 4.6 * feat: truncating fmt layer for terminal, full logs for web gateway Instead of truncating debug output at each LLM call site (fragile), use a custom MakeWriter on the fmt layer that caps each tracing event at 500 bytes before flushing to stderr. The web gateway WebLogLayer still receives full untruncated content for /api/logs/events SSE. Co-Authored-By: Claude Opus 4.6 * fix: UTF-8 safe truncation in truncate_for_preview, remove double truncation - Use char_indices() instead of byte-based slicing to find the cut point, preventing panics on multi-byte characters (emoji, CJK, etc.) - Remove redundant truncation in REPL channel (agent loop already truncates ToolResult previews to 200 chars) - Add 9 unit tests covering edge cases: empty, exact length, multi-byte UTF-8 (emoji, CJK), mixed scripts, newline collapsing, whitespace Addresses PR #65 review comments. Co-Authored-By: Claude Opus 4.6 --------- Co-authored-by: Claude Opus 4.6 --- src/agent/agent_loop.rs | 78 +++++++++- src/agent/mod.rs | 1 + src/channels/repl.rs | 10 +- src/lib.rs | 1 + src/llm/nearai_chat.rs | 5 +- src/main.rs | 6 +- src/tracing_fmt.rs | 319 ++++++++++++++++++++++++++++++++++++++++ 7 files changed, 412 insertions(+), 8 deletions(-) create mode 100644 src/tracing_fmt.rs diff --git a/src/agent/agent_loop.rs b/src/agent/agent_loop.rs index 9afd7bc2..18a7d6fc 100644 --- a/src/agent/agent_loop.rs +++ b/src/agent/agent_loop.rs @@ -28,7 +28,7 @@ use crate::tools::ToolRegistry; use crate::workspace::Workspace; /// Collapse a tool output string into a single-line preview for display. -fn truncate_for_preview(output: &str, max_chars: usize) -> String { +pub(crate) fn truncate_for_preview(output: &str, max_chars: usize) -> String { let collapsed: String = output .chars() .take(max_chars + 50) @@ -37,8 +37,14 @@ fn truncate_for_preview(output: &str, max_chars: usize) -> String { .split_whitespace() .collect::>() .join(" "); - if collapsed.len() > max_chars { - format!("{}...", &collapsed[..max_chars]) + // char_indices gives us byte offsets at char boundaries, so the slice is always valid UTF-8. + if collapsed.chars().count() > max_chars { + let byte_offset = collapsed + .char_indices() + .nth(max_chars) + .map(|(i, _)| i) + .unwrap_or(collapsed.len()); + format!("{}...", &collapsed[..byte_offset]) } else { collapsed } @@ -2627,4 +2633,70 @@ mod tests { assert!(detect_auth_awaiting("tool_activate", &result).is_none()); } + + // --- truncate_for_preview tests --- + + use super::truncate_for_preview; + + #[test] + fn test_truncate_short_input() { + assert_eq!(truncate_for_preview("hello", 10), "hello"); + } + + #[test] + fn test_truncate_empty_input() { + assert_eq!(truncate_for_preview("", 10), ""); + } + + #[test] + fn test_truncate_exact_length() { + assert_eq!(truncate_for_preview("hello", 5), "hello"); + } + + #[test] + fn test_truncate_over_limit() { + let result = truncate_for_preview("hello world, this is long", 10); + assert!(result.ends_with("...")); + // "hello worl" = 10 chars + "..." + assert_eq!(result, "hello worl..."); + } + + #[test] + fn test_truncate_collapses_newlines() { + let result = truncate_for_preview("line1\nline2\nline3", 100); + assert!(!result.contains('\n')); + assert_eq!(result, "line1 line2 line3"); + } + + #[test] + fn test_truncate_collapses_whitespace() { + let result = truncate_for_preview("hello world", 100); + assert_eq!(result, "hello world"); + } + + #[test] + fn test_truncate_multibyte_utf8() { + // Each emoji is 4 bytes. Truncating at char boundary must not panic. + let input = "๐Ÿ˜€๐Ÿ˜๐Ÿ˜‚๐Ÿคฃ๐Ÿ˜ƒ๐Ÿ˜„๐Ÿ˜…๐Ÿ˜†๐Ÿ˜‰๐Ÿ˜Š"; + let result = truncate_for_preview(input, 5); + assert!(result.ends_with("...")); + // First 5 chars = 5 emoji + assert_eq!(result, "๐Ÿ˜€๐Ÿ˜๐Ÿ˜‚๐Ÿคฃ๐Ÿ˜ƒ..."); + } + + #[test] + fn test_truncate_cjk_characters() { + // CJK chars are 3 bytes each in UTF-8. + let input = "ไฝ ๅฅฝไธ–็•Œๆต‹่ฏ•ๆ•ฐๆฎๅพˆ้•ฟ็š„ๅญ—็ฌฆไธฒ"; + let result = truncate_for_preview(input, 4); + assert_eq!(result, "ไฝ ๅฅฝไธ–็•Œ..."); + } + + #[test] + fn test_truncate_mixed_multibyte_and_ascii() { + let input = "hello ไธ–็•Œ foo"; + let result = truncate_for_preview(input, 8); + // 'h','e','l','l','o',' ','ไธ–','็•Œ' = 8 chars + assert_eq!(result, "hello ไธ–็•Œ..."); + } } diff --git a/src/agent/mod.rs b/src/agent/mod.rs index 1455c92c..a667b17d 100644 --- a/src/agent/mod.rs +++ b/src/agent/mod.rs @@ -26,6 +26,7 @@ pub mod task; pub mod undo; pub mod worker; +pub(crate) use agent_loop::truncate_for_preview; pub use agent_loop::{Agent, AgentDeps}; pub use compaction::{CompactionResult, ContextCompactor}; pub use context_monitor::{CompactionStrategy, ContextBreakdown, ContextMonitor}; diff --git a/src/channels/repl.rs b/src/channels/repl.rs index cbfd1c4a..ea91082b 100644 --- a/src/channels/repl.rs +++ b/src/channels/repl.rs @@ -33,9 +33,13 @@ use termimad::MadSkin; use tokio::sync::mpsc; use tokio_stream::wrappers::ReceiverStream; +use crate::agent::truncate_for_preview; use crate::channels::{Channel, IncomingMessage, MessageStream, OutgoingResponse, StatusUpdate}; use crate::error::ChannelError; +/// Max characters for thinking/status messages in the terminal. +const CLI_STATUS_MAX: usize = 200; + /// Slash commands available in the REPL. const SLASH_COMMANDS: &[&str] = &[ "/help", @@ -400,7 +404,8 @@ impl Channel for ReplChannel { match status { StatusUpdate::Thinking(msg) => { - eprintln!(" \x1b[90m\u{25CB} {msg}\x1b[0m"); + let display = truncate_for_preview(&msg, CLI_STATUS_MAX); + eprintln!(" \x1b[90m\u{25CB} {display}\x1b[0m"); } StatusUpdate::ToolStarted { name } => { eprintln!(" \x1b[33m\u{25CB} {name}\x1b[0m"); @@ -438,7 +443,8 @@ impl Channel for ReplChannel { } StatusUpdate::Status(msg) => { if debug || msg.contains("approval") || msg.contains("Approval") { - eprintln!(" \x1b[90m{msg}\x1b[0m"); + let display = truncate_for_preview(&msg, CLI_STATUS_MAX); + eprintln!(" \x1b[90m{display}\x1b[0m"); } } StatusUpdate::ApprovalNeeded { diff --git a/src/lib.rs b/src/lib.rs index 54313777..7185d3f3 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -58,6 +58,7 @@ pub mod secrets; pub mod settings; pub mod setup; pub mod tools; +pub mod tracing_fmt; pub mod util; pub mod worker; pub mod workspace; diff --git a/src/llm/nearai_chat.rs b/src/llm/nearai_chat.rs index 5ca5e95e..13a36a91 100644 --- a/src/llm/nearai_chat.rs +++ b/src/llm/nearai_chat.rs @@ -71,8 +71,9 @@ impl NearAiChatProvider { tracing::debug!("Sending request to NEAR AI Chat: {}", url); - // Log the request body for debugging tool call issues - if let Ok(json) = serde_json::to_string(body) { + if tracing::enabled!(tracing::Level::DEBUG) + && let Ok(json) = serde_json::to_string(body) + { tracing::debug!("NEAR AI Chat request body: {}", json); } diff --git a/src/main.rs b/src/main.rs index 1a933ee6..cc619eb8 100644 --- a/src/main.rs +++ b/src/main.rs @@ -305,7 +305,11 @@ async fn main() -> anyhow::Result<()> { tracing_subscriber::registry() .with(env_filter) - .with(tracing_subscriber::fmt::layer().with_target(false)) + .with( + tracing_subscriber::fmt::layer() + .with_target(false) + .with_writer(ironclaw::tracing_fmt::TruncatingStderr::default()), + ) .with(WebLogLayer::new(Arc::clone(&log_broadcaster))) .init(); diff --git a/src/tracing_fmt.rs b/src/tracing_fmt.rs new file mode 100644 index 00000000..f0d7073a --- /dev/null +++ b/src/tracing_fmt.rs @@ -0,0 +1,319 @@ +//! Truncating terminal writer for tracing. +//! +//! Tracing events from LLM providers can dump 10KB+ JSON bodies to stderr. +//! Rather than truncating at every call site (fragile, easy to miss), we +//! handle it at the writer level: the fmt layer gets a `TruncatingStderr` +//! that caps each event before flushing, while the web gateway `WebLogLayer` +//! still sees the full, untruncated content. +//! +//! ```text +//! tracing::debug!("body: {huge_json}") +//! | +//! v +//! tracing_subscriber::registry() +//! | +//! +-- fmt::layer().with_writer(TruncatingStderr) <-- caps at 500B +//! | \-- stderr (truncated) +//! | +//! \-- WebLogLayer (unchanged) +//! \-- SSE broadcast (full) +//! ``` + +use std::io::{self, Write}; + +use tracing_subscriber::fmt::MakeWriter; + +/// Maximum bytes per tracing event written to the terminal. +const TERMINAL_MAX_EVENT_BYTES: usize = 500; + +/// A `MakeWriter` that creates per-event buffers which truncate on flush. +/// +/// Each call to `make_writer()` returns an `EventBuffer`. All `write()` +/// calls accumulate into the buffer. When the buffer drops (after the fmt +/// layer finishes writing one event), it flushes to stderr, truncating if +/// the total exceeds `TERMINAL_MAX_EVENT_BYTES`. +#[derive(Clone)] +pub struct TruncatingStderr { + max_bytes: usize, +} + +impl Default for TruncatingStderr { + fn default() -> Self { + Self { + max_bytes: TERMINAL_MAX_EVENT_BYTES, + } + } +} + +impl TruncatingStderr { + #[cfg(test)] + fn with_max_bytes(max_bytes: usize) -> Self { + Self { max_bytes } + } +} + +impl<'a> MakeWriter<'a> for TruncatingStderr { + type Writer = EventBuffer; + + fn make_writer(&'a self) -> Self::Writer { + EventBuffer { + buf: Vec::with_capacity(256), + max_bytes: self.max_bytes, + #[cfg(test)] + sink: None, + } + } +} + +/// Per-event buffer that truncates on drop. +pub struct EventBuffer { + buf: Vec, + max_bytes: usize, + /// Test-only: capture output instead of writing to stderr. + #[cfg(test)] + sink: Option>>>, +} + +impl Write for EventBuffer { + fn write(&mut self, data: &[u8]) -> io::Result { + self.buf.extend_from_slice(data); + Ok(data.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +} + +/// Find the last valid UTF-8 char boundary at or before `pos` in `bytes`. +/// +/// Walks backwards from `pos` until we find a byte that isn't a UTF-8 +/// continuation byte (0x80..0xBF). Returns 0 if the entire prefix is +/// somehow invalid (shouldn't happen with valid UTF-8 input from tracing). +fn utf8_floor(bytes: &[u8], pos: usize) -> usize { + let mut i = pos; + // UTF-8 continuation bytes have the form 10xxxxxx (0x80..0xBF). + // Walk backwards past them to find the start of the last character. + while i > 0 && bytes[i] & 0xC0 == 0x80 { + i -= 1; + } + i +} + +impl Drop for EventBuffer { + fn drop(&mut self) { + if self.buf.is_empty() { + return; + } + + let output = if self.buf.len() <= self.max_bytes { + &self.buf[..] + } else { + // Truncate at a UTF-8 safe boundary + let cut = utf8_floor(&self.buf, self.max_bytes); + let suffix = format!("...[{}B total]\n", self.buf.len()); + let mut truncated = Vec::with_capacity(cut + suffix.len()); + // Strip trailing newline from the cut portion (we add our own via suffix) + let cut_slice = &self.buf[..cut]; + let trimmed = if cut_slice.last() == Some(&b'\n') { + &cut_slice[..cut_slice.len() - 1] + } else { + cut_slice + }; + truncated.extend_from_slice(trimmed); + truncated.extend_from_slice(suffix.as_bytes()); + + #[cfg(test)] + if let Some(ref sink) = self.sink { + let mut s = sink.lock().expect("test sink lock poisoned"); + s.extend_from_slice(&truncated); + return; + } + + let _ = io::stderr().write_all(&truncated); + return; + }; + + #[cfg(test)] + if let Some(ref sink) = self.sink { + let mut s = sink.lock().expect("test sink lock poisoned"); + s.extend_from_slice(output); + return; + } + + let _ = io::stderr().write_all(output); + } +} + +#[cfg(test)] +mod tests { + use std::sync::{Arc, Mutex}; + + use crate::tracing_fmt::{EventBuffer, TruncatingStderr, utf8_floor}; + + use std::io::Write; + + /// Helper: create an EventBuffer that captures output to a shared Vec + /// instead of writing to stderr. + fn test_buffer(max_bytes: usize) -> (EventBuffer, Arc>>) { + let sink = Arc::new(Mutex::new(Vec::new())); + let buf = EventBuffer { + buf: Vec::new(), + max_bytes, + sink: Some(Arc::clone(&sink)), + }; + (buf, sink) + } + + #[test] + fn test_short_event_not_truncated() { + let (mut buf, sink) = test_buffer(500); + buf.write_all(b"hello world\n").unwrap(); + drop(buf); + + let output = sink.lock().unwrap(); + assert_eq!(&*output, b"hello world\n"); + } + + #[test] + fn test_long_event_truncated() { + let (mut buf, sink) = test_buffer(20); + let data = "abcdefghijklmnopqrstuvwxyz0123456789\n"; + buf.write_all(data.as_bytes()).unwrap(); + let total = data.len(); + drop(buf); + + let output = sink.lock().unwrap(); + let output_str = String::from_utf8_lossy(&output); + // Should contain the suffix with total byte count + assert!( + output_str.contains(&format!("...[{}B total]", total)), + "expected truncation suffix, got: {}", + output_str + ); + // Should be shorter than the original + assert!(output.len() < total); + } + + #[test] + fn test_utf8_boundary_safe() { + // "Helloรฉ" = [72, 101, 108, 108, 111, 195, 169] + // ^-- 2-byte UTF-8 char + // If we truncate at 6 bytes, we'd land in the middle of 'รฉ'. + // utf8_floor should back up to byte 5 (start of 'รฉ' = 195). + let (mut buf, sink) = test_buffer(6); + let data = "Helloรฉ world"; + buf.write_all(data.as_bytes()).unwrap(); + drop(buf); + + let output = sink.lock().unwrap(); + let output_str = String::from_utf8(output.clone()); + assert!( + output_str.is_ok(), + "output should be valid UTF-8, got bytes: {:?}", + &*output + ); + let s = output_str.unwrap(); + assert!( + s.contains("...["), + "should be truncated with suffix, got: {}", + s + ); + // The truncated prefix must be valid UTF-8 up to the cut point. + // "Hello" (5 bytes) is the last valid cut before the 2-byte รฉ. + assert!( + s.starts_with("Hello"), + "should start with 'Hello', got: {}", + s + ); + } + + #[test] + fn test_utf8_floor_basic() { + // ASCII: every byte is a valid boundary + assert_eq!(utf8_floor(b"hello", 3), 3); + + // 2-byte UTF-8 char รฉ = [0xC3, 0xA9] + // Landing on the continuation byte (0xA9) should back up to 0xC3 + let bytes = "Hรฉ".as_bytes(); // [72, 0xC3, 0xA9] + assert_eq!(utf8_floor(bytes, 2), 1); // backs up to start of รฉ + + // 3-byte UTF-8 char (e.g. ใ‚ = [0xE3, 0x81, 0x82]) + let bytes = "aใ‚".as_bytes(); // [97, 0xE3, 0x81, 0x82] + assert_eq!(utf8_floor(bytes, 2), 1); // backs up past continuation to 0xE3 + assert_eq!(utf8_floor(bytes, 3), 1); // same: 0x82 is continuation, 0x81 is too + } + + #[test] + fn test_multiple_writes_accumulated() { + let (mut buf, sink) = test_buffer(500); + buf.write_all(b"hello ").unwrap(); + buf.write_all(b"world\n").unwrap(); + drop(buf); + + let output = sink.lock().unwrap(); + assert_eq!(&*output, b"hello world\n"); + } + + #[test] + fn test_empty_buffer_no_output() { + let (_buf, sink) = test_buffer(500); + // drop without writing + drop(_buf); + + let output = sink.lock().unwrap(); + assert!(output.is_empty()); + } + + #[test] + fn test_default_max_bytes() { + let writer = TruncatingStderr::default(); + assert_eq!(writer.max_bytes, 500); + } + + #[test] + fn test_custom_max_bytes() { + let writer = TruncatingStderr::with_max_bytes(100); + assert_eq!(writer.max_bytes, 100); + } + + #[test] + fn test_exactly_at_limit_not_truncated() { + let (mut buf, sink) = test_buffer(5); + buf.write_all(b"hello").unwrap(); + drop(buf); + + let output = sink.lock().unwrap(); + assert_eq!(&*output, b"hello"); + } + + #[test] + fn test_one_over_limit_truncated() { + let (mut buf, sink) = test_buffer(5); + buf.write_all(b"hello!").unwrap(); + drop(buf); + + let output = sink.lock().unwrap(); + let s = String::from_utf8_lossy(&output); + assert!(s.contains("...[6B total]"), "got: {}", s); + } + + #[test] + fn test_4byte_utf8_boundary() { + // 4-byte UTF-8 char: ๐„ž (musical symbol) = [0xF0, 0x9D, 0x84, 0x9E] + let data = "AB๐„žCD"; + // bytes: [65, 66, 0xF0, 0x9D, 0x84, 0x9E, 67, 68] + // Truncating at byte 4 lands in the middle of the 4-byte char + let (mut buf, sink) = test_buffer(4); + buf.write_all(data.as_bytes()).unwrap(); + drop(buf); + + let output = sink.lock().unwrap(); + let s = String::from_utf8(output.clone()); + assert!(s.is_ok(), "output must be valid UTF-8, got: {:?}", &*output); + let s = s.unwrap(); + // Should back up to byte 2 (just "AB"), since bytes 2..5 are all part of ๐„ž + assert!(s.starts_with("AB"), "expected 'AB', got: {}", s); + assert!(s.contains("...["), "should be truncated, got: {}", s); + } +}