From 2cb23d9293061486ed431e368b5904affeaf0f58 Mon Sep 17 00:00:00 2001 From: Salman Mohammed Date: Wed, 15 Jan 2025 13:44:29 -0500 Subject: [PATCH] feat: add more tracing logs, trim loaded prompt (#603) --- crates/goose-cli/src/commands/mcp.rs | 3 +++ crates/goose-cli/src/logging.rs | 21 +++++++++++++++------ crates/goose-server/src/commands/agent.rs | 2 +- crates/goose-server/src/commands/mcp.rs | 4 +++- crates/goose-server/src/logging.rs | 22 +++++++++++++++------- crates/goose-server/src/routes/system.rs | 1 + crates/goose/src/prompt_template.rs | 6 +++--- crates/mcp-client/src/client.rs | 7 +++---- crates/mcp-client/src/transport/stdio.rs | 13 ++++++++++--- crates/mcp-server/src/lib.rs | 7 +++---- 10 files changed, 57 insertions(+), 29 deletions(-) diff --git a/crates/goose-cli/src/commands/mcp.rs b/crates/goose-cli/src/commands/mcp.rs index 291e4d620a..bda870e4b4 100644 --- a/crates/goose-cli/src/commands/mcp.rs +++ b/crates/goose-cli/src/commands/mcp.rs @@ -6,6 +6,9 @@ use mcp_server::{BoundedService, ByteTransport, Server}; use tokio::io::{stdin, stdout}; pub async fn run_server(name: &str) -> Result<()> { + // Initialize logging + crate::logging::setup_logging(Some(&format!("mcp-{name}")))?; + tracing::info!("Starting MCP server"); let router: Option> = match name { diff --git a/crates/goose-cli/src/logging.rs b/crates/goose-cli/src/logging.rs index 0af6e2012f..36bf91c391 100644 --- a/crates/goose-cli/src/logging.rs +++ b/crates/goose-cli/src/logging.rs @@ -34,17 +34,21 @@ fn get_log_directory() -> Result { /// - File-based logging with JSON formatting (DEBUG level) /// - Console output for development (INFO level) /// - Optional Langfuse integration (DEBUG level) -pub fn setup_logging(session_name: Option<&str>) -> Result<()> { +pub fn setup_logging(name: Option<&str>) -> Result<()> { // Set up file appender for goose module logs let log_dir = get_log_directory()?; let timestamp = chrono::Local::now().format("%Y%m%d_%H%M%S").to_string(); + // Create log file name by prefixing with timestamp + let log_filename = if name.is_some() { + format!("{}-{}.log", timestamp, name.unwrap()) + } else { + format!("{}.log", timestamp) + }; + // Create non-rolling file appender for detailed logs - let file_appender = tracing_appender::rolling::RollingFileAppender::new( - Rotation::NEVER, - log_dir, - &format!("{}.log", session_name.unwrap_or(×tamp)), - ); + let file_appender = + tracing_appender::rolling::RollingFileAppender::new(Rotation::NEVER, log_dir, log_filename); // Create JSON file logging layer with all logs (DEBUG and above) let file_layer = fmt::layer() @@ -68,6 +72,11 @@ pub fn setup_logging(session_name: Option<&str>) -> Result<()> { let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { // Set default levels for different modules EnvFilter::new("") + // Set mcp-server module to DEBUG + .add_directive("mcp_server=debug".parse().unwrap()) + // Set mcp-client to DEBUG + .add_directive("mcp_client=debug".parse().unwrap()) + // Set goose module to DEBUG .add_directive("goose=debug".parse().unwrap()) // Set goose-cli to INFO .add_directive("goose_cli=info".parse().unwrap()) diff --git a/crates/goose-server/src/commands/agent.rs b/crates/goose-server/src/commands/agent.rs index 8031f1e90c..5355bbe65b 100644 --- a/crates/goose-server/src/commands/agent.rs +++ b/crates/goose-server/src/commands/agent.rs @@ -6,7 +6,7 @@ use tracing::info; pub async fn run() -> Result<()> { // Initialize logging - crate::logging::setup_logging()?; + crate::logging::setup_logging(Some(&"goosed"))?; // Load configuration let settings = configuration::Settings::new()?; diff --git a/crates/goose-server/src/commands/mcp.rs b/crates/goose-server/src/commands/mcp.rs index 069963e7c2..dead113d96 100644 --- a/crates/goose-server/src/commands/mcp.rs +++ b/crates/goose-server/src/commands/mcp.rs @@ -6,8 +6,10 @@ use mcp_server::{BoundedService, ByteTransport, Server}; use tokio::io::{stdin, stdout}; pub async fn run(name: &str) -> Result<()> { - tracing::info!("Starting MCP server"); + // Initialize logging + crate::logging::setup_logging(Some(&format!("mcp-{name}")))?; + tracing::info!("Starting MCP server"); let router: Option> = match name { "developer" => Some(Box::new(RouterService(DeveloperRouter::new()))), "developer2" => Some(Box::new(RouterService(Developer2Router::new()))), diff --git a/crates/goose-server/src/logging.rs b/crates/goose-server/src/logging.rs index b195c17fcd..1077f25133 100644 --- a/crates/goose-server/src/logging.rs +++ b/crates/goose-server/src/logging.rs @@ -34,17 +34,21 @@ fn get_log_directory() -> Result { /// - File-based logging with JSON formatting (DEBUG level) /// - Console output for development (INFO level) /// - Optional Langfuse integration (DEBUG level) -pub fn setup_logging() -> Result<()> { +pub fn setup_logging(name: Option<&str>) -> Result<()> { // Set up file appender for goose module logs let log_dir = get_log_directory()?; let timestamp = chrono::Local::now().format("%Y%m%d_%H%M%S").to_string(); + // Create log file name by prefixing with timestamp + let log_filename = if name.is_some() { + format!("{}-{}.log", timestamp, name.unwrap()) + } else { + format!("{}.log", timestamp) + }; + // Create non-rolling file appender for detailed logs - let file_appender = tracing_appender::rolling::RollingFileAppender::new( - Rotation::NEVER, - log_dir, - &format!("goosed_{}.log", timestamp), - ); + let file_appender = + tracing_appender::rolling::RollingFileAppender::new(Rotation::NEVER, log_dir, log_filename); // Create JSON file logging layer let file_layer = fmt::layer() @@ -67,7 +71,11 @@ pub fn setup_logging() -> Result<()> { let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { // Set default levels for different modules EnvFilter::new("") - // Set goose module to INFO only + // Set mcp-server module to DEBUG + .add_directive("mcp_server=debug".parse().unwrap()) + // Set mcp-client to DEBUG + .add_directive("mcp_client=debug".parse().unwrap()) + // Set goose module to DEBUG .add_directive("goose=debug".parse().unwrap()) // Set goose-server to INFO .add_directive("goose_server=info".parse().unwrap()) diff --git a/crates/goose-server/src/routes/system.rs b/crates/goose-server/src/routes/system.rs index 8d0ceb03c8..7d49963a79 100644 --- a/crates/goose-server/src/routes/system.rs +++ b/crates/goose-server/src/routes/system.rs @@ -23,6 +23,7 @@ async fn add_system( if secret_key != state.secret_key { return Err(StatusCode::UNAUTHORIZED); } + let mut agent = state.agent.lock().await; let agent = agent.as_mut().ok_or(StatusCode::PRECONDITION_REQUIRED)?; let response = agent.add_system(request).await; diff --git a/crates/goose/src/prompt_template.rs b/crates/goose/src/prompt_template.rs index 2f81386cfc..e7652d83f4 100644 --- a/crates/goose/src/prompt_template.rs +++ b/crates/goose/src/prompt_template.rs @@ -11,7 +11,7 @@ pub fn load_prompt(template: &str, context_data: &T) -> Result( @@ -75,7 +75,7 @@ mod tests { let result = load_prompt_file(file_path, &context).unwrap(); assert_eq!( result, - "This prompt is only used for testing.\n\nHello, Alice! You are 30 years old.\n" + "This prompt is only used for testing.\n\nHello, Alice! You are 30 years old." ); } @@ -133,7 +133,7 @@ mod tests { context.insert("tools".to_string(), tools); let result = load_prompt(template, &context).unwrap(); - let expected = "### Tool Descriptions\n"; + let expected = "### Tool Descriptions"; assert_eq!(result, expected); } } diff --git a/crates/mcp-client/src/client.rs b/crates/mcp-client/src/client.rs index 5dc242c05e..1ce9adb626 100644 --- a/crates/mcp-client/src/client.rs +++ b/crates/mcp-client/src/client.rs @@ -39,11 +39,10 @@ pub enum Error { #[error("Error from mcp-server: {0}")] ServerBoxError(BoxError), - #[error("Call to '{server}' failed for '{method}' with params '{params}'. {source}")] + #[error("Call to '{server}' failed for '{method}'. {source}")] McpServerError { method: String, server: String, - params: Value, #[source] source: BoxError, }, @@ -146,7 +145,7 @@ where .map_err(|e| Error::McpServerError { server: self.server_info.as_ref().unwrap().name.clone(), method: method.to_string(), - params: params.clone(), + // we don't need include params because it can be really large source: Box::new(e.into()), })?; @@ -208,7 +207,7 @@ where .map_err(|e| Error::McpServerError { server: self.server_info.as_ref().unwrap().name.clone(), method: method.to_string(), - params: params.clone(), + // we don't need include params because it can be really large source: Box::new(e.into()), })?; diff --git a/crates/mcp-client/src/transport/stdio.rs b/crates/mcp-client/src/transport/stdio.rs index baa93888ed..35bd1785a6 100644 --- a/crates/mcp-client/src/transport/stdio.rs +++ b/crates/mcp-client/src/transport/stdio.rs @@ -43,6 +43,11 @@ impl StdioActor { } // EOF Ok(_) => { if let Ok(message) = serde_json::from_str::(&line) { + tracing::debug!( + message = ?message, + "Received incoming message" + ); + if let JsonRpcMessage::Response(response) = &message { if let Some(id) = &response.id { pending_requests.respond(&id.to_string(), Ok(message)).await; @@ -52,7 +57,7 @@ impl StdioActor { line.clear(); } Err(e) => { - eprintln!("Error reading line: {}", e); + tracing::error!(error = ?e, "Error reading line"); break; } } @@ -75,6 +80,8 @@ impl StdioActor { } }; + tracing::debug!(message = ?transport_msg.message, "Sending outgoing message"); + if let Some(response_tx) = transport_msg.response_tx { if let JsonRpcMessage::Request(request) = &transport_msg.message { if let Some(id) = &request.id { @@ -87,13 +94,13 @@ impl StdioActor { .write_all(format!("{}\n", message_str).as_bytes()) .await { - eprintln!("write_all failed: {:?}", e); + tracing::error!(error = ?e, "Error writing message to child process"); pending_requests.clear().await; break; } if let Err(e) = stdin.flush().await { - eprintln!("flush failed: {:?}", e); + tracing::error!(error = ?e, "Error flushing message to child process"); pending_requests.clear().await; break; } diff --git a/crates/mcp-server/src/lib.rs b/crates/mcp-server/src/lib.rs index 512ff549b3..de63666789 100644 --- a/crates/mcp-server/src/lib.rs +++ b/crates/mcp-server/src/lib.rs @@ -57,6 +57,9 @@ where Ok(s) => s, Err(e) => return Poll::Ready(Some(Err(TransportError::Utf8(e)))), }; + // Log incoming message here before serde conversion to + // track incomplete chunks which are not valid JSON + tracing::info!(json = %line, "incoming message"); // Parse JSON and validate message format match serde_json::from_str::(&line) { @@ -77,10 +80,6 @@ where )))); } - tracing::info!( - json = %line, - "incoming message" - ); // Now try to parse as proper message match serde_json::from_value::(value) { Ok(msg) => Poll::Ready(Some(Ok(msg))),