fix(core): add logs for stuck subagent task completion

Author: wsp1911

src/crates/core/src/agentic/coordination/coordinator.rs

@@ -2721,6 +2721,19 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
         let initial_deadline =
             timeout_seconds.map(|seconds| Instant::now() + Duration::from_secs(seconds));
         let (deadline_tx, mut deadline_rx) = watch::channel(initial_deadline);
+        let subagent_started_at = Instant::now();
+        let parent_session_id = subagent_parent_info
+            .as_ref()
+            .map(|info| info.session_id.as_str())
+            .unwrap_or("-");
+        let parent_dialog_turn_id = subagent_parent_info
+            .as_ref()
+            .map(|info| info.dialog_turn_id.as_str())
+            .unwrap_or("-");
+        let parent_tool_call_id = subagent_parent_info
+            .as_ref()
+            .map(|info| info.tool_call_id.as_str())
+            .unwrap_or("-");
 
         let context_profile_policy = self.context_profile_policy_for_subagent(
             &agent_type,
@@ -2909,6 +2922,17 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
         let execution_engine = self.execution_engine.clone();
         let tool_pipeline = self.tool_pipeline.clone();
         let agent_type_for_execution = agent_type.clone();
+        debug!(
+            "Subagent execution task starting: agent_type={}, session_id={}, dialog_turn_id={}, parent_session_id={}, parent_dialog_turn_id={}, parent_tool_call_id={}, timeout_seconds={:?}, wait_ms={}",
+            agent_type,
+            session_id,
+            dialog_turn_id,
+            parent_session_id,
+            parent_dialog_turn_id,
+            parent_tool_call_id,
+            timeout_seconds,
+            wait_ms
+        );
         let mut execution_task = tokio::spawn(async move {
             execution_engine
                 .execute_dialog_turn(
@@ -2974,6 +2998,23 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
             }
         };
 
+        let execution_outcome_label = match &execution_outcome {
+            SubagentExecutionOutcome::Completed(_) => "completed",
+            SubagentExecutionOutcome::Cancelled => "cancelled",
+            SubagentExecutionOutcome::TimedOut => "timed_out",
+        };
+        debug!(
+            "Subagent execution outcome resolved: agent_type={}, session_id={}, dialog_turn_id={}, parent_session_id={}, parent_dialog_turn_id={}, parent_tool_call_id={}, outcome={}, duration_ms={}",
+            agent_type,
+            session_id,
+            dialog_turn_id,
+            parent_session_id,
+            parent_dialog_turn_id,
+            parent_tool_call_id,
+            execution_outcome_label,
+            subagent_started_at.elapsed().as_millis()
+        );
+
         let result = match execution_outcome {
             SubagentExecutionOutcome::Completed(join_result) => match join_result {
                 Ok(result) => result,
@@ -3203,21 +3244,69 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
         };
 
         // Clean up subagent session resources after successful execution
-        debug!("Starting subagent resource cleanup: session={}", session_id);
+        debug!(
+            "Subagent successful execution produced final text: agent_type={}, session_id={}, dialog_turn_id={}, parent_session_id={}, parent_dialog_turn_id={}, parent_tool_call_id={}, text_len={}, duration_ms={}",
+            agent_type,
+            session_id,
+            dialog_turn_id,
+            parent_session_id,
+            parent_dialog_turn_id,
+            parent_tool_call_id,
+            response_text.len(),
+            subagent_started_at.elapsed().as_millis()
+        );
+        let cleanup_started_at = Instant::now();
+        debug!(
+            "Subagent cleanup starting after successful execution: agent_type={}, session_id={}, dialog_turn_id={}, parent_session_id={}, parent_dialog_turn_id={}, parent_tool_call_id={}",
+            agent_type,
+            session_id,
+            dialog_turn_id,
+            parent_session_id,
+            parent_dialog_turn_id,
+            parent_tool_call_id
+        );
         if let Err(e) = self.cleanup_subagent_resources(&session_id).await {
             warn!(
                 "Failed to cleanup subagent resources: session={}, error={}",
                 session_id, e
             );
         } else {
             debug!(
-                "Subagent resource cleanup completed: session={}",
-                session_id
+                "Subagent cleanup completed after successful execution: agent_type={}, session_id={}, dialog_turn_id={}, parent_session_id={}, parent_dialog_turn_id={}, parent_tool_call_id={}, cleanup_duration_ms={}",
+                agent_type,
+                session_id,
+                dialog_turn_id,
+                parent_session_id,
+                parent_dialog_turn_id,
+                parent_tool_call_id,
+                cleanup_started_at.elapsed().as_millis()
             );
         }
+        debug!(
+            "Subagent timeout registry removal starting: agent_type={}, session_id={}, dialog_turn_id={}",
+            agent_type, session_id, dialog_turn_id
+        );
         let mut registry = self.subagent_timeout_registry.write().await;
         registry.remove(&session_id);
+        debug!(
+            "Subagent timeout registry removal completed: agent_type={}, session_id={}, dialog_turn_id={}, total_duration_ms={}",
+            agent_type,
+            session_id,
+            dialog_turn_id,
+            subagent_started_at.elapsed().as_millis()
+        );
 
+        debug!(
+            "Subagent result returning to caller: agent_type={}, session_id={}, dialog_turn_id={}, parent_session_id={}, parent_dialog_turn_id={}, parent_tool_call_id={}, status=completed, text_len={}, total_duration_ms={}",
+            agent_type,
+            session_id,
+            dialog_turn_id,
+            parent_session_id,
+            parent_dialog_turn_id,
+            parent_tool_call_id,
+            response_text.len(),
+            subagent_started_at.elapsed().as_millis()
+        );
         Ok(SubagentResult::completed(response_text))
     }
 
@@ -3442,17 +3531,21 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
     ///
     /// Release resources occupied by subagent session (sandbox, etc.) and delete session
     async fn cleanup_subagent_resources(&self, session_id: &str) -> BitFunResult<()> {
-        debug!(
-            "Starting subagent resource cleanup: session_id={}",
-            session_id
-        );
+        let cleanup_started_at = Instant::now();
+        debug!("Starting subagent resource cleanup: session_id={}", session_id);
 
         // Clean up snapshot system resources
         if let Some(workspace_path) = self
             .session_manager
             .get_session(session_id)
             .and_then(|session| session.config.workspace_path.map(std::path::PathBuf::from))
         {
+            debug!(
+                "Subagent cleanup stage starting: session_id={}, stage=snapshot_cleanup, workspace_path={}",
+                session_id,
+                workspace_path.display()
+            );
+            let stage_started_at = Instant::now();
             if let Ok(snapshot_manager) =
                 crate::service::snapshot::ensure_snapshot_manager_for_workspace(&workspace_path)
             {
@@ -3470,6 +3563,11 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
                     );
                 }
             }
+            debug!(
+                "Subagent cleanup stage completed: session_id={}, stage=snapshot_cleanup, duration_ms={}",
+                session_id,
+                stage_started_at.elapsed().as_millis()
+            );
         }
 
         // Delete the subagent session itself, including runtime context and persisted turn data.
@@ -3479,6 +3577,12 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
             .and_then(|session| session.config.workspace_path.map(std::path::PathBuf::from));
 
         if let Some(workspace_path) = workspace_path {
+            debug!(
+                "Subagent cleanup stage starting: session_id={}, stage=session_delete, workspace_path={}",
+                session_id,
+                workspace_path.display()
+            );
+            let stage_started_at = Instant::now();
             if let Err(e) = self
                 .session_manager
                 .delete_session(&workspace_path, session_id)
@@ -3491,6 +3595,11 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
             } else {
                 debug!("Subagent session deleted: session={}", session_id);
             }
+            debug!(
+                "Subagent cleanup stage completed: session_id={}, stage=session_delete, duration_ms={}",
+                session_id,
+                stage_started_at.elapsed().as_millis()
+            );
         } else {
             warn!(
                 "Failed to delete subagent session because workspace_path is missing: session={}",
@@ -3499,8 +3608,9 @@ Update the persona files and delete BOOTSTRAP.md as soon as bootstrap is complet
         }
 
         debug!(
-            "Subagent resource cleanup completed: session_id={}",
-            session_id
+            "Subagent resource cleanup completed: session_id={}, duration_ms={}",
+            session_id,
+            cleanup_started_at.elapsed().as_millis()
         );
         Ok(())
     }

src/crates/core/src/agentic/session/session_manager.rs

@@ -24,12 +24,14 @@ use crate::service::session::{
 use crate::service::snapshot::ensure_snapshot_manager_for_workspace;
 use crate::util::errors::{BitFunError, BitFunResult};
 use crate::util::sanitize_plain_model_output;
+use crate::util::timing::elapsed_ms_u64;
 use dashmap::DashMap;
 use log::{debug, error, info, warn};
 use serde_json::json;
 use std::collections::HashSet;
 use std::path::{Path, PathBuf};
 use std::sync::Arc;
+use std::time::Instant;
 use std::time::{Duration, SystemTime};
 use tokio::time;
 
@@ -1529,7 +1531,20 @@ impl SessionManager {
         workspace_path: &Path,
         session_id: &str,
     ) -> BitFunResult<()> {
+        let delete_started_at = Instant::now();
+        debug!(
+            "Session deletion started: session_id={}, workspace_path={}, persistence_enabled={}",
+            session_id,
+            workspace_path.display(),
+            self.config.enable_persistence
+        );
+
         // 1. Clean up snapshot system resources (including physical snapshot files)
+        let snapshot_stage_started_at = Instant::now();
+        debug!(
+            "Session deletion stage starting: session_id={}, stage=snapshot_cleanup",
+            session_id
+        );
         if let Ok(snapshot_manager) = ensure_snapshot_manager_for_workspace(workspace_path) {
             let snapshot_service = snapshot_manager.get_snapshot_service();
             let snapshot_service = snapshot_service.read().await;
@@ -1542,17 +1557,47 @@ impl SessionManager {
                 );
             }
         }
+        debug!(
+            "Session deletion stage completed: session_id={}, stage=snapshot_cleanup, duration_ms={}",
+            session_id,
+            elapsed_ms_u64(snapshot_stage_started_at)
+        );
 
+        let context_stage_started_at = Instant::now();
+        debug!(
+            "Session deletion stage starting: session_id={}, stage=context_store_delete",
+            session_id
+        );
         self.context_store.delete_session(session_id);
+        debug!(
+            "Session deletion stage completed: session_id={}, stage=context_store_delete, duration_ms={}",
+            session_id,
+            elapsed_ms_u64(context_stage_started_at)
+        );
 
         // 2. Delete persisted data
         if self.config.enable_persistence {
+            let persistence_stage_started_at = Instant::now();
+            debug!(
+                "Session deletion stage starting: session_id={}, stage=persistence_delete",
+                session_id
+            );
             self.persistence_manager
                 .delete_session(workspace_path, session_id)
                 .await?;
+            debug!(
+                "Session deletion stage completed: session_id={}, stage=persistence_delete, duration_ms={}",
+                session_id,
+                elapsed_ms_u64(persistence_stage_started_at)
+            );
         }
 
         if let Some(cron) = crate::service::cron::get_global_cron_service() {
+            let cron_stage_started_at = Instant::now();
+            debug!(
+                "Session deletion stage starting: session_id={}, stage=cron_cleanup",
+                session_id
+            );
             match cron.delete_jobs_for_session(session_id).await {
                 Ok(removed) if removed > 0 => {
                     info!(
@@ -1568,12 +1613,23 @@ impl SessionManager {
                     );
                 }
             }
+            debug!(
+                "Session deletion stage completed: session_id={}, stage=cron_cleanup, duration_ms={}",
+                session_id,
+                elapsed_ms_u64(cron_stage_started_at)
+            );
         }
 
         // 3. Clean up associated Terminal session
         use crate::service::terminal::TerminalApi;
         if let Ok(terminal_api) = TerminalApi::from_singleton() {
             let binding = terminal_api.session_manager().binding();
+            let terminal_stage_started_at = Instant::now();
+            debug!(
+                "Session deletion stage starting: session_id={}, stage=terminal_binding_cleanup, has_binding={}",
+                session_id,
+                binding.has(session_id)
+            );
             if binding.has(session_id) {
                 if let Err(e) = binding.remove(session_id).await {
                     warn!("Failed to cleanup associated Terminal session: {}", e);
@@ -1584,12 +1640,32 @@ impl SessionManager {
                     );
                 }
             }
+            debug!(
+                "Session deletion stage completed: session_id={}, stage=terminal_binding_cleanup, duration_ms={}",
+                session_id,
+                elapsed_ms_u64(terminal_stage_started_at)
+            );
         }
 
         // 4. Remove from memory
+        let memory_stage_started_at = Instant::now();
+        debug!(
+            "Session deletion stage starting: session_id={}, stage=in_memory_remove",
+            session_id
+        );
         self.sessions.remove(session_id);
+        debug!(
+            "Session deletion stage completed: session_id={}, stage=in_memory_remove, duration_ms={}",
+            session_id,
+            elapsed_ms_u64(memory_stage_started_at)
+        );
 
-        info!("Session deletion completed: session_id={}", session_id);
+        info!(
+            "Session deletion completed: session_id={}, workspace_path={}, duration_ms={}",
+            session_id,
+            workspace_path.display(),
+            elapsed_ms_u64(delete_started_at)
+        );
 
         Ok(())
     }