feat: Add structured tracing to ACP runner for debugging (#52)

## Summary

- Added file-based logging via tuicore's `.use_disk_logs(true)`
configuration
- Instrumented ACP runner with tracing macros (info/debug/warn)
throughout lifecycle
- Logs written to `~/.nori-cli/logs/` with automatic daily rotation
- Fixed pre-existing test failure in `model_backend_ordering_test.rs`

## Changes

**src/main.rs**: Enabled disk logs in TuiApp builder
**src/acp_runner.rs**: Added ~15 tracing calls covering:
- ACP initialization and handshake
- Session creation and management  
- Prompt handling
- File operations (read/write)
- Permission requests
- All error conditions

**tests/model_backend_ordering_test.rs**: Fixed test to use
`BACKEND_OPTIONS` constant

## Test Plan

- [x] All 107 existing tests pass
- [x] Cargo build succeeds
- [x] Cargo clippy passes (pre-existing warnings only)
- [x] Manual verification: logs created in `~/.nori-cli/logs/`
- [x] Manual verification: ACP lifecycle events logged with appropriate
levels

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-authored-by: Claude <noreply@anthropic.com>

Author: CSRessel

Cargo.lock

@@ -32,9 +32,9 @@ tui-components = { path = "./tui-components" }
  tuicore = { git = "https://github.com/CSRessel/terminal-input-debug", rev = "a2f66fd" }
 tracing = "0.1.41"
 libc = "0.2"
- # dev deps: insta tempfile tokio-test tracing tracing-subscriber tracing-appender
 
 [dev-dependencies]
 tempfile = "3"
 once_cell = "1"
 insta = "1.43"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }

Cargo.toml

@@ -27,6 +27,7 @@ use tokio::time::timeout;
 use tokio_stream::wrappers::UnboundedReceiverStream;
 use tokio_util::compat::{TokioAsyncReadCompatExt, TokioAsyncWriteCompatExt};
 use tokio_util::sync::CancellationToken;
+use tracing::{debug, info, warn};
 
 /// Configuration for an ACP agent
 #[derive(Debug, Clone)]
@@ -162,6 +163,8 @@ impl Client for AcpClientHandler {
         &self,
         args: RequestPermissionRequest,
     ) -> AcpResult<RequestPermissionResponse> {
+        debug!("Permission requested for tool call");
+
         // Check if session was cancelled
         if self.cancel_token.is_cancelled() {
             return Ok(RequestPermissionResponse {
@@ -185,6 +188,8 @@ impl Client for AcpClientHandler {
             .map(|opt| opt.id.clone())
             .ok_or_else(agent_client_protocol::Error::internal_error)?;
 
+        debug!("Permission granted: option_id={:?}", option_id);
+
         Ok(RequestPermissionResponse {
             outcome: RequestPermissionOutcome::Selected { option_id },
             meta: None,
@@ -198,6 +203,8 @@ impl Client for AcpClientHandler {
     }
 
     async fn read_text_file(&self, args: ReadTextFileRequest) -> AcpResult<ReadTextFileResponse> {
+        debug!("Reading file: {:?}", args.path);
+
         // Ensure the path is within the working directory
         let requested_path = PathBuf::from(&args.path);
         let canonical_path = if requested_path.is_absolute() {
@@ -212,14 +219,23 @@ impl Client for AcpClientHandler {
                 content,
                 meta: None,
             }),
-            Err(_e) => Err(agent_client_protocol::Error::internal_error()),
+            Err(_e) => {
+                warn!("File read failed: {:?}", canonical_path);
+                Err(agent_client_protocol::Error::internal_error())
+            }
         }
     }
 
     async fn write_text_file(
         &self,
         args: WriteTextFileRequest,
     ) -> AcpResult<WriteTextFileResponse> {
+        debug!(
+            "Writing file: {:?}, content_length={}",
+            args.path,
+            args.content.len()
+        );
+
         // Ensure the path is within the working directory
         let requested_path = PathBuf::from(&args.path);
         let canonical_path = if requested_path.is_absolute() {
@@ -232,13 +248,20 @@ impl Client for AcpClientHandler {
         if let Some(parent) = canonical_path.parent()
             && let Err(_e) = tokio::fs::create_dir_all(parent).await
         {
+            warn!(
+                "Failed to create parent directories for: {:?}",
+                canonical_path
+            );
             return Err(agent_client_protocol::Error::internal_error());
         }
 
         // Write the file
         match tokio::fs::write(&canonical_path, &args.content).await {
             Ok(_) => Ok(WriteTextFileResponse { meta: None }),
-            Err(_e) => Err(agent_client_protocol::Error::internal_error()),
+            Err(_e) => {
+                warn!("File write failed: {:?}", canonical_path);
+                Err(agent_client_protocol::Error::internal_error())
+            }
         }
     }
 
@@ -470,6 +493,9 @@ async fn run_connection_inner(
         tokio::task::spawn_local(async move {
             let mut updates = session_update_rx;
             while let Some(update) = updates.recv().await {
+                // Log all session updates to file
+                debug!("Session update received: {:?}", update);
+
                 // Send debug event for all session updates
                 let debug_event = ConversationEvent::UnknownEvent {
                     raw: format!("{update:?}"),
@@ -503,6 +529,8 @@ async fn run_connection_inner(
         });
     }
 
+    info!("Starting ACP connection initialization");
+
     let init_request = InitializeRequest {
         protocol_version: acp::V1,
         client_capabilities: ClientCapabilities {
@@ -522,17 +550,24 @@ async fn run_connection_inner(
         meta: None,
     };
 
+    debug!(
+        "Sending initialize request: protocol_version={:?}",
+        init_request.protocol_version
+    );
+
     let init_response =
         match timeout(Duration::from_secs(30), connection.initialize(init_request)).await {
             Ok(Ok(response)) => response,
             Ok(Err(err)) => {
+                warn!("ACP initialization failed: {}", err);
                 let message = format!("Initialize failed: {err}");
                 if let Some(tx) = handshake_tx.take() {
                     let _ = tx.send(Err(message.clone()));
                 }
                 return Err(message);
             }
             Err(_) => {
+                warn!("ACP initialization timeout after 30s");
                 let message = "Initialization timeout after 30s".to_string();
                 if let Some(tx) = handshake_tx.take() {
                     let _ = tx.send(Err(message.clone()));
@@ -546,12 +581,21 @@ async fn run_connection_inner(
             "Unsupported protocol version: {:?}",
             init_response.protocol_version
         );
+        warn!(
+            "Unsupported protocol version: {:?}",
+            init_response.protocol_version
+        );
         if let Some(tx) = handshake_tx.take() {
             let _ = tx.send(Err(err.clone()));
         }
         return Err(err);
     }
 
+    info!(
+        "ACP initialized successfully: protocol_version={:?}, agent_info={:?}",
+        init_response.protocol_version, init_response.agent_info
+    );
+
     // Send debug event for successful initialization
     let _ = event_tx.send(BackendEvent::Conversation(ConversationEvent::SystemEvent {
         subtype: "acp_initialized".to_string(),
@@ -561,6 +605,8 @@ async fn run_connection_inner(
         )),
     }));
 
+    debug!("Creating new ACP session: cwd={:?}", cwd);
+
     let session_response = match connection
         .new_session(NewSessionRequest {
             cwd: cwd.clone(),
@@ -571,6 +617,7 @@ async fn run_connection_inner(
     {
         Ok(response) => response,
         Err(err) => {
+            warn!("ACP session creation failed: {}", err);
             let message = format!("Session creation failed: {err}");
             if let Some(tx) = handshake_tx.take() {
                 let _ = tx.send(Err(message.clone()));
@@ -580,6 +627,8 @@ async fn run_connection_inner(
     };
     let session_id = session_response.session_id.clone();
 
+    info!("ACP session created: session_id={}", session_id);
+
     // Send debug event for session creation
     let _ = event_tx.send(BackendEvent::Conversation(ConversationEvent::SystemEvent {
         subtype: "acp_session_created".to_string(),
@@ -611,8 +660,9 @@ async fn run_connection_inner(
         details: Some(format!("Prompt length: {} chars", prompt.len())),
     }));
 
+    let prompt_len = prompt.len();
     let prompt_request = PromptRequest {
-        session_id,
+        session_id: session_id.clone(),
         prompt: vec![ContentBlock::Text(TextContent {
             annotations: None,
             text: prompt,
@@ -621,8 +671,14 @@ async fn run_connection_inner(
         meta: None,
     };
 
+    debug!(
+        "Sending prompt to ACP agent: session_id={}, prompt_length={}",
+        session_id, prompt_len
+    );
+
     match connection.prompt(prompt_request).await {
         Ok(response) => {
+            info!("Prompt completed: stop_reason={:?}", response.stop_reason);
             {
                 let mut tracker = inline_tracker.borrow_mut();
                 tracker.commit_all(&event_tx);
@@ -634,6 +690,7 @@ async fn run_connection_inner(
             ));
         }
         Err(err) => {
+            warn!("Prompt failed: {}", err);
             {
                 let mut tracker = inline_tracker.borrow_mut();
                 tracker.abort_all(&event_tx);

src/acp_runner.rs

@@ -248,10 +248,10 @@ The Agent Client Protocol (ACP) is a standardized protocol for communication bet
    - 7 passing unit tests covering all translation paths
 
 3. **AcpClientHandler** - Full `Client` trait implementation:
-   - `request_permission()` - Auto-approves by selecting first "allow" option (AllowOnce/AllowAlways)
-   - `session_notification()` - Forwards SessionUpdate to event stream via mpsc channel
-   - `read_text_file()` - Reads from working directory, handles absolute/relative paths
-   - `write_text_file()` - Writes with auto-created parent directories
+   - `request_permission()` - Auto-approves by selecting first "allow" option (AllowOnce/AllowAlways) - logs permission requests and granted options at debug level
+   - `session_notification()` - Forwards SessionUpdate to event stream via mpsc channel - logs all session updates at debug level
+   - `read_text_file()` - Reads from working directory, handles absolute/relative paths - logs file path at debug level, logs failures at warn level
+   - `write_text_file()` - Writes with auto-created parent directories - logs file path and content length at debug level, logs failures at warn level
    - Terminal methods blocked - returns `method_not_found` errors (security requirement)
    - Uses cancellation token to return `Cancelled` outcome if session cancelled mid-flight
 
@@ -266,6 +266,30 @@ User Prompt → AcpAgentRunner::spawn_stream() → JSON-RPC over stdio → Agent
               SessionUpdate → translate_session_update → ConversationEvent → UI
 ```
 
+**Structured Tracing** (@/src/acp_runner.rs):
+- ACP runner includes comprehensive tracing instrumentation using Rust's `tracing` crate
+- **Lifecycle events** (info level):
+  - Connection initialization start: "Starting ACP connection initialization"
+  - Successful initialization with protocol version and agent info
+  - Session creation with session ID
+  - Prompt completion with stop reason
+- **Detailed events** (debug level):
+  - Initialize request with protocol version
+  - Session creation request with working directory
+  - Prompt sending with session ID and prompt length
+  - All session updates (SessionUpdate messages from protocol)
+  - Permission requests and granted options
+  - File operations (read/write) with paths and content lengths
+- **Error events** (warn level):
+  - Initialization failures with error message
+  - Initialization timeouts (30s)
+  - Unsupported protocol versions
+  - Session creation failures
+  - Prompt execution failures
+  - File operation failures (read/write)
+- **Log output**: Writes to `~/.nori-cli/logs/` when disk logging enabled in TuiApp
+- **Purpose**: Debug ACP transport issues, understand lifecycle timing, investigate file operations without disrupting TUI
+
 **What's NOT Yet Implemented** (See @/ACP_IMPLEMENTATION_PLAN.md):
 - `AcpAgentRunner::spawn_stream()` - Core method to spawn agent and manage JSON-RPC lifecycle
 - JSON-RPC transport layer over stdin/stdout

src/backends/docs.md

@@ -26,7 +26,7 @@ pub mod ui;           // Rendering functions for each mode
 ```
 
 **Entry Point** (@/src/main.rs):
-- `main()`: Parses CLI arguments via clap::Parser, validates agent name (exits with error if invalid), reads from stdin if piped, then sets up terminal (raw mode, Viewport::Inline(8)), runs async event loop, restores terminal on exit with cursor positioning to next line before disabling raw mode to ensure shell prompt appears cleanly below TUI content
+- `main()`: Parses CLI arguments via clap::Parser, validates agent name (exits with error if invalid), reads from stdin if piped, then sets up terminal (raw mode, Viewport::Inline(8)), runs async event loop, restores terminal on exit with cursor positioning to next line before disabling raw mode to ensure shell prompt appears cleanly below TUI content - enables disk-based logging via `TuiApp::builder().use_disk_logs(true)` which writes structured logs to ~/.nori-cli/logs/ directory using tuicore's tracing-appender integration with daily log rotation
 - `run_app(agent_index, initial_message)`: Core event loop using tokio::select! to handle messages and render at ~30 fps interval - accepts optional agent_index to skip agent selection screen and optional initial_message to pre-fill textarea - includes mpsc channel for syncing `last_ctrl_c_time` to event handler task - removed loading frame increment logic after adopting Shimmer component
 - `handle_event_simple()` / `handle_key_simple()`: Convert crossterm key events to Message based on current mode - Ctrl-C detection happens FIRST before overlay/install prompt checks to ensure double Ctrl-C always works
 - `get_backend()`: Factory function that returns appropriate backend based on selected_agent_index, using the centralized BACKEND_OPTIONS constant for consistent backend ordering
@@ -217,4 +217,24 @@ pub mod ui;           // Rendering functions for each mode
 - **Follows existing pattern**: UserMessage rendering uses exact same pipeline as StreamEvent rendering (lines 88-112) - both call render_event(), wrap_text_to_width(), and terminal.insert_before() in identical sequence
 - **Slash command handling**: Slash commands bypass user message rendering entirely - they are not stored as conversation events and should not appear in chat history
 
+### Things to Know
+
+**Structured Tracing and Observability** (@/src/acp_runner.rs, @/src/main.rs):
+- Parallel logging system using Rust's `tracing` crate alongside existing TUI debug events
+- **Log file location**: `~/.nori-cli/logs/` with daily rotation handled by tuicore's tracing-appender integration
+- **Enabled via**: `TuiApp::builder().use_disk_logs(true)` in main.rs - opt-in configuration
+- **Log levels in ACP runner**:
+  - `info!()`: Lifecycle events (initialization start/success, session creation, prompt completion)
+  - `debug!()`: Detailed events (requests sent, file operations, permissions, session updates)
+  - `warn!()`: Error conditions (init failures, session failures, prompt failures, file I/O errors)
+- **ACP lifecycle instrumentation** (@/src/acp_runner.rs:163-628):
+  - Connection initialization: logs protocol version negotiation and agent info
+  - Session management: logs session ID, working directory on creation
+  - Prompt handling: logs prompt length, session ID, stop reason on completion
+  - File operations: logs file paths and content lengths for read/write operations
+  - Permission requests: logs tool call permissions and selected options
+  - Session updates: logs all ACP SessionUpdate messages as debug events
+- **Non-intrusive design**: Tracing calls parallel existing functionality without replacing TUI debug events or changing business logic
+- **Use case**: Debugging ACP transport issues, understanding lifecycle timing, investigating file operation failures without disrupting TUI interaction
+
 Created and maintained by Nori.

src/docs.md

@@ -63,7 +63,10 @@ async fn main() -> Result<()> {
     // Determine initial message (CLI arg takes precedence over stdin)
     let initial_message = cli.message.or(stdin_message);
 
-    let mut tui_app = TuiApp::builder("nori-cli").inline(20).build();
+    let mut tui_app = TuiApp::builder("nori-cli")
+        .inline(20)
+        .use_disk_logs(true)
+        .build();
 
     let mut terminal = tui_app.init()?;
     run_app(&mut terminal, agent_index, initial_message).await?;