feat: add [BASIC_EXEC] traces for start, tool, scheduler, webhook execution
All checks were successful
BotServer CI/CD / build (push) Successful in 3m18s

This commit is contained in:
Rodrigo Rodriguez (Pragmatismo) 2026-04-13 18:16:01 -03:00
parent 99572f0dc5
commit 8a65afbfc5
6 changed files with 26 additions and 17 deletions

View file

@ -331,8 +331,12 @@ impl ScriptService {
pub fn run(&mut self, ast_content: &str) -> Result<Dynamic, Box<EvalAltResult>> { pub fn run(&mut self, ast_content: &str) -> Result<Dynamic, Box<EvalAltResult>> {
let ast = match self.engine.compile(ast_content) { let ast = match self.engine.compile(ast_content) {
Ok(ast) => ast, 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) self.engine.eval_ast_with_scope(&mut self.scope, &ast)
} }

View file

@ -257,6 +257,7 @@ impl ToolExecutor {
arguments: &Value, arguments: &Value,
) -> ToolExecutionResult { ) -> ToolExecutionResult {
let tool_call_id = format!("tool_{}", uuid::Uuid::new_v4()); 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 // Create ScriptService
let mut script_service = ScriptService::new(state.clone(), session.clone()); let mut script_service = ScriptService::new(state.clone(), session.clone());
@ -276,15 +277,17 @@ impl ToolExecutor {
// Set variable in script scope // Set variable in script scope
if let Err(e) = script_service.set_variable(key, &value_str) { 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) // Run the pre-compiled .ast content (compilation happens only in Drive Monitor)
match script_service.run(ast_content) { match script_service.run(ast_content) {
Ok(result) => { Ok(result) => {
trace!("Tool '{}' executed successfully", tool_name); log::info!("[BASIC_EXEC] Tool '{}' completed successfully", tool_name);
// Convert result to string // Convert result to string
let result_str = result.to_string(); let result_str = result.to_string();
@ -297,6 +300,7 @@ impl ToolExecutor {
} }
} }
Err(e) => { Err(e) => {
log::error!("[BASIC_EXEC] Tool '{}' execution error: {}", tool_name, e);
let error_msg = format!("Execution error: {}", e); let error_msg = format!("Execution error: {}", e);
Self::log_tool_error(bot_name, tool_name, &error_msg); Self::log_tool_error(bot_name, tool_name, &error_msg);
let user_message = Self::format_user_friendly_error(tool_name, &error_msg); let user_message = Self::format_user_friendly_error(tool_name, &error_msg);

View file

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

View file

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

View file

@ -335,10 +335,14 @@ impl TaskScheduler {
let registry = self.task_registry.clone(); let registry = self.task_registry.clone();
let running_tasks = self.running_tasks.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 handle = tokio::spawn(async move {
let execution_id = Uuid::new_v4(); let execution_id = Uuid::new_v4();
let started_at = Utc::now(); let started_at = Utc::now();
log::trace!("[BASIC_EXEC] Task '{}' execution_id={}, started_at={}", task.name, execution_id, started_at);
let _execution = TaskExecution { let _execution = TaskExecution {
id: execution_id, id: execution_id,
scheduled_task_id: task_id, scheduled_task_id: task_id,

View file

@ -254,6 +254,7 @@ pub async fn handle_webhook(
Err(err) => return err.0, 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)); debug!("Raw webhook body: {}", String::from_utf8_lossy(&body));
let payload: WhatsAppWebhook = match serde_json::from_slice(&body) { let payload: WhatsAppWebhook = match serde_json::from_slice(&body) {