worlds simplest logging to see where things are blocked (#3888)

Co-authored-by: Michael Neale <michael.neale@gmail.com>

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<PathBuf> {
-    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<String>) -> Result<PathBuf> {
-    // 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"));
 
-    // Create date-based subdirectory
-    let date_str = test_date.unwrap_or_else(|| {
+    let component_dir = base_log_dir.join("cli");
+
+    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);

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<PathBuf> {
-    // 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.

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 {

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

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;

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<PathBuf> {
+    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]);
+            }
+        }
+    }
+}

crates/goose/src/providers/api_client.rs

@@ -341,6 +341,12 @@ impl<'a> ApiRequestBuilder<'a> {
     }
 
     pub async fn response_post(self, payload: &Value) -> Result<Response> {
+        // 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?)
     }