feat: add [BASIC_EXEC] traces for start, tool, scheduler, webhook execution

Co-authored-by: Qwen-Coder <qwen-coder@alibabacloud.com>

src/basic/mod.rs

@@ -331,8 +331,12 @@ impl ScriptService {
     pub fn run(&mut self, ast_content: &str) -> Result<Dynamic, Box<EvalAltResult>> {
         let ast = match self.engine.compile(ast_content) {
             Ok(ast) => ast,
-            Err(e) => return Err(Box::new(e.into())),
+            Err(e) => {
+                log::error!("[BASIC_EXEC] Failed to compile AST: {}", e);
+                return Err(Box::new(e.into()));
+            }
         };
+        log::trace!("[BASIC_EXEC] Executing compiled AST ({} chars)", ast_content.len());
         self.engine.eval_ast_with_scope(&mut self.scope, &ast)
     }
 

src/core/bot/tool_executor.rs

@@ -257,6 +257,7 @@ impl ToolExecutor {
         arguments: &Value,
     ) -> ToolExecutionResult {
         let tool_call_id = format!("tool_{}", uuid::Uuid::new_v4());
+        log::info!("[BASIC_EXEC] Tool '{}' starting execution (bot={}, session={})", tool_name, bot_name, session.id);
 
         // Create ScriptService
         let mut script_service = ScriptService::new(state.clone(), session.clone());
@@ -276,15 +277,17 @@ impl ToolExecutor {
 
                 // Set variable in script scope
                 if let Err(e) = script_service.set_variable(key, &value_str) {
-                    warn!("Failed to set variable '{}': {}", key, e);
+                    log::warn!("[BASIC_EXEC] Failed to set variable '{}': {}", key, e);
                 }
             }
         }
 
+        log::trace!("[BASIC_EXEC] Tool '{}' running .ast ({} chars)", tool_name, ast_content.len());
+
         // Run the pre-compiled .ast content (compilation happens only in Drive Monitor)
         match script_service.run(ast_content) {
             Ok(result) => {
-                trace!("Tool '{}' executed successfully", tool_name);
+                log::info!("[BASIC_EXEC] Tool '{}' completed successfully", tool_name);
 
                 // Convert result to string
                 let result_str = result.to_string();
@@ -297,6 +300,7 @@ impl ToolExecutor {
                 }
             }
             Err(e) => {
+                log::error!("[BASIC_EXEC] Tool '{}' execution error: {}", tool_name, e);
                 let error_msg = format!("Execution error: {}", e);
                 Self::log_tool_error(bot_name, tool_name, &error_msg);
                 let user_message = Self::format_user_friendly_error(tool_name, &error_msg);
@@ -339,12 +343,48 @@ impl ToolExecutor {
         user_id: &Uuid,
     ) -> ToolExecutionResult {
         let tool_call_id = format!("direct_{}", Uuid::new_v4());
-        
+
         info!(
             "[TOOL_EXEC] Direct tool invocation: '{}' for bot '{}', session '{}'",
             tool_name, bot_name, session_id
         );
 
+        // Ensure websocket_session_id and channel are set on the session so TALK can route correctly
+        {
+            let mut sm = state.session_manager.lock().await;
+            if let Ok(Some(sess)) = sm.get_session_by_id(*session_id) {
+                let needs_update = if let serde_json::Value::Object(ref map) = sess.context_data {
+                    !map.contains_key("websocket_session_id") || !map.contains_key("channel")
+                } else {
+                    true
+                };
+                if needs_update {
+                    let mut updated = sess.clone();
+                    if let serde_json::Value::Object(ref mut map) = updated.context_data {
+                        if !map.contains_key("websocket_session_id") {
+                            map.insert(
+                                "websocket_session_id".to_string(),
+                                serde_json::Value::String(session_id.to_string()),
+                            );
+                        }
+                        if !map.contains_key("channel") {
+                            map.insert(
+                                "channel".to_string(),
+                                serde_json::Value::String("web".to_string()),
+                            );
+                        }
+                    } else {
+                        let mut map = serde_json::Map::new();
+                        map.insert("websocket_session_id".to_string(), serde_json::Value::String(session_id.to_string()));
+                        map.insert("channel".to_string(), serde_json::Value::String("web".to_string()));
+                        updated.context_data = serde_json::Value::Object(map);
+                    }
+                    let context_json = serde_json::to_string(&updated.context_data).unwrap_or_default();
+                    let _ = sm.update_session_context(session_id, user_id, context_json);
+                }
+            }
+        }
+
         let tool_call = ParsedToolCall {
             id: tool_call_id.clone(),
             tool_name: tool_name.to_string(),

src/llm/glm.rs

@@ -316,14 +316,12 @@ impl LLMProvider for GLMClient {
                                         }
                                     }
 
-                                    // GLM-4.7 on NVIDIA sends text via reasoning_content when thinking is enabled
-                                    // content may be null; we accept both fields
-                                    let content = delta.get("content").and_then(|c| c.as_str())
-                                        .or_else(|| delta.get("reasoning_content").and_then(|c| c.as_str()));
-
-                                    if let Some(text) = content {
-                                        if !text.is_empty() {
-                                            match tx.send(text.to_string()).await {
+                                    // GLM-4.7 on NVIDIA sends thinking text via reasoning_content
+                                    // The actual user-facing response is in content field
+                                    // We ONLY send content — never reasoning_content (internal thinking)
+                                    if let Some(content) = delta.get("content").and_then(|c| c.as_str()) {
+                                        if !content.is_empty() {
+                                            match tx.send(content.to_string()).await {
                                                 Ok(_) => {},
                                                 Err(e) => {
                                                     error!("Failed to send to channel: {}", e);

src/llm/kimi.rs

@@ -312,12 +312,10 @@ impl LLMProvider for KimiClient {
                                         }
                                     }
 
-                                    // Kimi K2.5 sends text via reasoning_content (thinking mode)
-                                    // content may be null; we accept both fields
-                                    let text = delta.get("content").and_then(|c| c.as_str())
-                                        .or_else(|| delta.get("reasoning_content").and_then(|c| c.as_str()));
-
-                                    if let Some(text) = text {
+                                    // Kimi K2.5 sends thinking via reasoning_content
+                                    // The actual user-facing response is in content field
+                                    // We ONLY send content — never reasoning_content (internal thinking)
+                                    if let Some(text) = delta.get("content").and_then(|c| c.as_str()) {
                                         if !text.is_empty() {
                                             let _ = tx.send(text.to_string()).await;
                                         }

src/tasks/scheduler.rs

@@ -335,10 +335,14 @@ impl TaskScheduler {
         let registry = self.task_registry.clone();
         let running_tasks = self.running_tasks.clone();
 
+        log::info!("[BASIC_EXEC] Scheduled task '{}' starting execution (task_id={}, type={})", task.name, task_id, task.task_type);
+
         let handle = tokio::spawn(async move {
             let execution_id = Uuid::new_v4();
             let started_at = Utc::now();
 
+            log::trace!("[BASIC_EXEC] Task '{}' execution_id={}, started_at={}", task.name, execution_id, started_at);
+
             let _execution = TaskExecution {
                 id: execution_id,
                 scheduled_task_id: task_id,

src/whatsapp/mod.rs

@@ -254,6 +254,7 @@ pub async fn handle_webhook(
         Err(err) => return err.0,
     };
 
+    log::info!("[BASIC_EXEC] WhatsApp webhook received for bot_id={}", bot_id);
     debug!("Raw webhook body: {}", String::from_utf8_lossy(&body));
 
     let payload: WhatsAppWebhook = match serde_json::from_slice(&body) {