diff --git a/crates/goose-cli/src/logging.rs b/crates/goose-cli/src/logging.rs index 4ffacaaa15d3..99a39a0c2f3c 100644 --- a/crates/goose-cli/src/logging.rs +++ b/crates/goose-cli/src/logging.rs @@ -1,6 +1,4 @@ use anyhow::{Context, Result}; -use etcetera::{choose_app_strategy, AppStrategy}; -use std::fs; use std::path::PathBuf; use std::sync::Arc; use std::sync::Once; @@ -21,33 +19,36 @@ static INIT: Once = Once::new(); /// Returns the directory where log files should be stored. /// Creates the directory structure if it doesn't exist. fn get_log_directory() -> Result { - get_log_directory_with_date(None) + goose::logging::get_log_directory("cli", true) } /// Internal function that allows specifying a custom date string for testing +#[cfg(test)] fn get_log_directory_with_date(test_date: Option) -> Result { - // choose_app_strategy().state_dir() - // - macOS/Linux: ~/.local/state/goose/logs/cli - // - Windows: ~\AppData\Roaming\Block\goose\data\logs\cli - // - Windows has no convention for state_dir, use data_dir instead - let home_dir = choose_app_strategy(crate::APP_STRATEGY.clone()) - .context("HOME environment variable not set")?; + use etcetera::{choose_app_strategy, AppStrategy}; + use goose::config::APP_STRATEGY; + + let home_dir = + choose_app_strategy(APP_STRATEGY.clone()).context("HOME environment variable not set")?; let base_log_dir = home_dir - .in_state_dir("logs/cli") - .unwrap_or_else(|| home_dir.in_data_dir("logs/cli")); + .in_state_dir("logs") + .unwrap_or_else(|| home_dir.in_data_dir("logs")); + + let component_dir = base_log_dir.join("cli"); - // Create date-based subdirectory - let date_str = test_date.unwrap_or_else(|| { + let log_dir = if let Some(date_str) = test_date { + component_dir.join(date_str) + } else { + // Create date-based subdirectory let now = chrono::Local::now(); - now.format("%Y-%m-%d").to_string() - }); - let date_dir = base_log_dir.join(date_str); + component_dir.join(now.format("%Y-%m-%d").to_string()) + }; // Ensure log directory exists - fs::create_dir_all(&date_dir).context("Failed to create log directory")?; + std::fs::create_dir_all(&log_dir).context("Failed to create log directory")?; - Ok(date_dir) + Ok(log_dir) } /// Sets up the logging infrastructure for the application. @@ -274,14 +275,14 @@ mod tests { println!("Log directory: {}", log_dir.display()); println!("Test directory: {}", test_dir.display()); if log_dir.exists() { - for entry in fs::read_dir(&log_dir).unwrap() { + for entry in std::fs::read_dir(&log_dir).unwrap() { let entry = entry.unwrap(); if entry.path().extension().map_or(false, |ext| ext == "log") { - fs::remove_file(entry.path()).unwrap(); + std::fs::remove_file(entry.path()).unwrap(); } } } else { - fs::create_dir_all(&log_dir).unwrap(); + std::fs::create_dir_all(&log_dir).unwrap(); } println!("Log directory created: {}", log_dir.exists()); @@ -306,7 +307,7 @@ mod tests { println!("Log directory exists: {}", log_dir.exists()); // Check if there are any log files directly - let all_files = fs::read_dir(&log_dir) + let all_files = std::fs::read_dir(&log_dir) .unwrap_or_else(|e| { println!("Error reading log directory: {}", e); panic!("Failed to read log directory: {}", e); @@ -331,12 +332,12 @@ mod tests { format!("{}.log", timestamp) }; let log_path = log_dir.join(&log_filename); - fs::write(&log_path, "Test log content").unwrap(); + std::fs::write(&log_path, "Test log content").unwrap(); println!("Created test log file: {}", log_path.display()); } // Read directory again after potential manual creation - let entries = fs::read_dir(&log_dir) + let entries = std::fs::read_dir(&log_dir) .unwrap_or_else(|e| { println!("Error reading log directory: {}", e); panic!("Failed to read log directory: {}", e); diff --git a/crates/goose-server/src/logging.rs b/crates/goose-server/src/logging.rs index 948c917903aa..026176538dba 100644 --- a/crates/goose-server/src/logging.rs +++ b/crates/goose-server/src/logging.rs @@ -1,6 +1,4 @@ use anyhow::{Context, Result}; -use etcetera::{choose_app_strategy, AppStrategy}; -use std::fs; use std::path::PathBuf; use tracing_appender::rolling::Rotation; use tracing_subscriber::{ @@ -8,31 +6,12 @@ use tracing_subscriber::{ Registry, }; -use goose::config::APP_STRATEGY; use goose::tracing::{langfuse_layer, otlp_layer}; /// Returns the directory where log files should be stored. /// Creates the directory structure if it doesn't exist. fn get_log_directory() -> Result { - // choose_app_strategy().state_dir() - // - macOS/Linux: ~/.local/state/goose/logs/server - // - Windows: ~\AppData\Roaming\Block\goose\data\logs\server - // - Windows has no convention for state_dir, use data_dir instead - let home_dir = - choose_app_strategy(APP_STRATEGY.clone()).context("HOME environment variable not set")?; - - let base_log_dir = home_dir - .in_state_dir("logs/server") - .unwrap_or_else(|| home_dir.in_data_dir("logs/server")); - - // Create date-based subdirectory - let now = chrono::Local::now(); - let date_dir = base_log_dir.join(now.format("%Y-%m-%d").to_string()); - - // Ensure log directory exists - fs::create_dir_all(&date_dir).context("Failed to create log directory")?; - - Ok(date_dir) + goose::logging::get_log_directory("server", true) } /// Sets up the logging infrastructure for the application. diff --git a/crates/goose/src/agents/agent.rs b/crates/goose/src/agents/agent.rs index bb5c37747cbc..5e3eee242d8e 100644 --- a/crates/goose/src/agents/agent.rs +++ b/crates/goose/src/agents/agent.rs @@ -437,8 +437,14 @@ impl Agent { }; } - let sub_recipe_manager = self.sub_recipe_manager.lock().await; - let result: ToolCallResult = if sub_recipe_manager.is_sub_recipe_tool(&tool_call.name) { + debug!("WAITING_TOOL_START: {}", tool_call.name); + let result: ToolCallResult = if self + .sub_recipe_manager + .lock() + .await + .is_sub_recipe_tool(&tool_call.name) + { + let sub_recipe_manager = self.sub_recipe_manager.lock().await; sub_recipe_manager .dispatch_sub_recipe_tool_call( &tool_call.name, @@ -616,6 +622,8 @@ impl Agent { }) }; + debug!("WAITING_TOOL_END: {}", tool_call.name); + ( request_id, Ok(ToolCallResult { diff --git a/crates/goose/src/agents/reply_parts.rs b/crates/goose/src/agents/reply_parts.rs index 14cbc7888e50..846657265330 100644 --- a/crates/goose/src/agents/reply_parts.rs +++ b/crates/goose/src/agents/reply_parts.rs @@ -4,6 +4,7 @@ use std::sync::Arc; use async_stream::try_stream; use futures::stream::StreamExt; +use tracing::debug; use super::super::agents::Agent; use crate::conversation::message::{Message, MessageContent, ToolRequest}; @@ -173,14 +174,18 @@ impl Agent { let provider = provider.clone(); let mut stream = if provider.supports_streaming() { - provider + debug!("WAITING_LLM_STREAM_START"); + let msg_stream = provider .stream( system_prompt.as_str(), messages_for_provider.messages(), &tools, ) - .await? + .await?; + debug!("WAITING_LLM_STREAM_END"); + msg_stream } else { + debug!("WAITING_LLM_START"); let (message, mut usage) = provider .complete( system_prompt.as_str(), @@ -188,6 +193,7 @@ impl Agent { &tools, ) .await?; + debug!("WAITING_LLM_END"); // Ensure we have token counts for non-streaming case usage diff --git a/crates/goose/src/lib.rs b/crates/goose/src/lib.rs index d0046941f57a..2504e3ab714c 100644 --- a/crates/goose/src/lib.rs +++ b/crates/goose/src/lib.rs @@ -2,6 +2,7 @@ pub mod agents; pub mod config; pub mod context_mgmt; pub mod conversation; +pub mod logging; pub mod model; pub mod oauth; pub mod permission; diff --git a/crates/goose/src/logging.rs b/crates/goose/src/logging.rs new file mode 100644 index 000000000000..90aa977e08c8 --- /dev/null +++ b/crates/goose/src/logging.rs @@ -0,0 +1,154 @@ +use anyhow::{Context, Result}; +use etcetera::{choose_app_strategy, AppStrategy}; +use std::fs; +use std::path::PathBuf; + +use crate::config::APP_STRATEGY; + +/// Returns the directory where log files should be stored for a specific component. +/// Creates the directory structure if it doesn't exist. +/// +/// # Arguments +/// +/// * `component` - The component name (e.g., "cli", "server", "debug") +/// * `use_date_subdir` - Whether to create a date-based subdirectory +/// +/// # Returns +/// +/// The path to the log directory for the specified component +pub fn get_log_directory(component: &str, use_date_subdir: bool) -> Result { + let home_dir = + choose_app_strategy(APP_STRATEGY.clone()).context("HOME environment variable not set")?; + + let base_log_dir = home_dir + .in_state_dir("logs") + .unwrap_or_else(|| home_dir.in_data_dir("logs")); + + let component_dir = base_log_dir.join(component); + + let log_dir = if use_date_subdir { + // Create date-based subdirectory + let now = chrono::Local::now(); + component_dir.join(now.format("%Y-%m-%d").to_string()) + } else { + component_dir + }; + + // Ensure log directory exists + fs::create_dir_all(&log_dir).context("Failed to create log directory")?; + + Ok(log_dir) +} + +#[cfg(test)] +mod tests { + use super::*; + use std::fs; + + #[test] + fn test_get_log_directory_basic_functionality() { + // Test basic directory creation without date subdirectory + let result = get_log_directory("cli", false); + assert!(result.is_ok()); + + let log_dir = result.unwrap(); + + // Verify the directory was created and has correct structure + assert!(log_dir.exists()); + assert!(log_dir.is_dir()); + + let path_str = log_dir.to_string_lossy(); + assert!(path_str.contains("cli")); + assert!(path_str.contains("logs")); + + // Verify we can write to the directory + let test_file = log_dir.join("test.log"); + assert!(fs::write(&test_file, "test log content").is_ok()); + let _ = fs::remove_file(&test_file); + } + + #[test] + fn test_get_log_directory_with_date_subdir() { + // Test date-based subdirectory creation + let result = get_log_directory("server", true); + assert!(result.is_ok()); + + let log_dir = result.unwrap(); + + // Verify the directory was created + assert!(log_dir.exists()); + assert!(log_dir.is_dir()); + + let path_str = log_dir.to_string_lossy(); + assert!(path_str.contains("server")); + assert!(path_str.contains("logs")); + + // Verify date format (YYYY-MM-DD) is present + let now = chrono::Local::now(); + let date_str = now.format("%Y-%m-%d").to_string(); + assert!(path_str.contains(&date_str)); + + // Verify path structure: logs -> component -> date + let logs_pos = path_str.find("logs").unwrap(); + let component_pos = path_str.find("server").unwrap(); + let date_pos = path_str.find(&date_str).unwrap(); + assert!(logs_pos < component_pos); + assert!(component_pos < date_pos); + } + + #[test] + fn test_get_log_directory_idempotent() { + // Test that multiple calls return the same result and don't fail + let component = "debug"; + + let result1 = get_log_directory(component, false); + assert!(result1.is_ok()); + let log_dir1 = result1.unwrap(); + + let result2 = get_log_directory(component, false); + assert!(result2.is_ok()); + let log_dir2 = result2.unwrap(); + + // Both calls should return the same path and directory should exist + assert_eq!(log_dir1, log_dir2); + assert!(log_dir1.exists()); + assert!(log_dir2.exists()); + + // Test same behavior with date subdirectories + let result3 = get_log_directory(component, true); + assert!(result3.is_ok()); + let log_dir3 = result3.unwrap(); + + let result4 = get_log_directory(component, true); + assert!(result4.is_ok()); + let log_dir4 = result4.unwrap(); + + assert_eq!(log_dir3, log_dir4); + assert!(log_dir3.exists()); + } + + #[test] + fn test_get_log_directory_different_components() { + // Test that different components create different directories + let components = ["cli", "server", "debug"]; + let mut created_dirs = Vec::new(); + + for component in &components { + let result = get_log_directory(component, false); + assert!(result.is_ok(), "Failed for component: {}", component); + + let log_dir = result.unwrap(); + assert!(log_dir.exists()); + assert!(log_dir.to_string_lossy().contains(component)); + + created_dirs.push(log_dir); + } + + // Verify all directories are different + for i in 0..created_dirs.len() { + for j in i + 1..created_dirs.len() { + assert_ne!(created_dirs[i], created_dirs[j]); + } + } + } +} diff --git a/crates/goose/src/providers/api_client.rs b/crates/goose/src/providers/api_client.rs index 0ce3b05ba4c9..821148bae757 100644 --- a/crates/goose/src/providers/api_client.rs +++ b/crates/goose/src/providers/api_client.rs @@ -341,6 +341,12 @@ impl<'a> ApiRequestBuilder<'a> { } pub async fn response_post(self, payload: &Value) -> Result { + // Log the JSON payload being sent to the LLM + tracing::debug!( + "LLM_REQUEST: {}", + serde_json::to_string(payload).unwrap_or_else(|_| "{}".to_string()) + ); + let request = self.send_request(|url, client| client.post(url)).await?; Ok(request.json(payload).send().await?) }