GeneralBots/botserver
2
1
Fork 0
Code Issues Pull requests Projects Releases 323 Packages Wiki Activity Actions

chore: update dependencies and formatting
All checks were successful
BotServer CI / build (push) Successful in 7m30s
Details

Browse source
This commit is contained in:
Rodrigo Rodriguez (Pragmatismo) 2026-02-22 15:55:39 -03:00
parent affb702e90
commit 1856215d05
26 changed files with 226 additions and 280 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

46
src/auto_task/app_generator.rs
View file

@ -1015,7 +1015,7 @@ impl AppGenerator {
}; };
// Mark "Analyzing Request" as completed // Mark "Analyzing Request" as completed
info!("[PHASE1->2] Marking Analyzing Request as Completed"); info!(" Marking Analyzing Request as Completed");
self.update_manifest_section(SectionType::Validation, SectionStatus::Completed); self.update_manifest_section(SectionType::Validation, SectionStatus::Completed);
self.broadcast_manifest_update(); self.broadcast_manifest_update();
@ -1069,7 +1069,7 @@ impl AppGenerator {
let tables = Self::convert_llm_tables(&llm_app.tables); let tables = Self::convert_llm_tables(&llm_app.tables);
if !tables.is_empty() { if !tables.is_empty() {
info!("[PHASE2] Setting Database & Models section to Running"); info!(" Setting Database & Models section to Running");
self.update_manifest_section(SectionType::DatabaseModels, SectionStatus::Running); self.update_manifest_section(SectionType::DatabaseModels, SectionStatus::Running);
self.broadcast_manifest_update(); self.broadcast_manifest_update();
self.update_manifest_child( self.update_manifest_child(
@ -1282,7 +1282,7 @@ impl AppGenerator {
// Debug: List all sections before update // Debug: List all sections before update
if let Some(ref manifest) = self.manifest { if let Some(ref manifest) = self.manifest {
info!("[PHASE2B] Current manifest sections:"); info!(" Current manifest sections:");
for (i, s) in manifest.sections.iter().enumerate() { for (i, s) in manifest.sections.iter().enumerate() {
info!( info!(
"[PHASE2B] [{}] {:?} = '{}' status={:?}", "[PHASE2B] [{}] {:?} = '{}' status={:?}",
@ -1301,7 +1301,7 @@ impl AppGenerator {
for idx in files_needing_content { for idx in files_needing_content {
let filename = llm_app.files[idx].filename.clone(); let filename = llm_app.files[idx].filename.clone();
generated_count += 1; generated_count += 1;
info!("[PHASE2B] Starting generation for file: {}", filename); info!(" Starting generation for file: {}", filename);
self.add_terminal_output( self.add_terminal_output(
&format!("Generating `{filename}`..."), &format!("Generating `{filename}`..."),
TerminalLineType::Info, TerminalLineType::Info,
@ -1783,11 +1783,11 @@ impl AppGenerator {
match std::fs::read_to_string(&prompt_path) { match std::fs::read_to_string(&prompt_path) {
Ok(content) => { Ok(content) => {
info!("[APP_GENERATOR] Loaded prompt from {:?} ({} chars)", prompt_path, content.len()); info!("Loaded prompt from {:?} ({} chars)", prompt_path, content.len());
content content
} }
Err(e) => { Err(e) => {
warn!("[APP_GENERATOR] Failed to load APP_GENERATOR_PROMPT.md: {}, using fallback", e); warn!("Failed to load APP_GENERATOR_PROMPT.md: {}, using fallback", e);
Self::get_fallback_prompt().to_string() Self::get_fallback_prompt().to_string()
} }
} }
@ -1876,7 +1876,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
intent_preview intent_preview
); );
let response = self.call_llm(&prompt, bot_id).await?; let response = self.call_llm(&prompt, bot_id).await?;
info!("[PHASE1] Project plan received, parsing..."); info!(" Project plan received, parsing...");
Self::parse_project_plan(&response, intent) Self::parse_project_plan(&response, intent)
} }
@ -1894,7 +1894,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
"[PHASE1_PARSE] Response preview: {}", "[PHASE1_PARSE] Response preview: {}",
response_preview.replace('\n', "\\n") response_preview.replace('\n', "\\n")
); );
info!("[PHASE1_PARSE] Has APP_START: {}, Has TABLES_START: {}, Has FILES_PLAN: {}, Has TOOLS_PLAN: {}", trace!(" Has APP_START: {}, Has TABLES_START: {}, Has FILES_PLAN: {}, Has TOOLS_PLAN: {}",
response.contains("<<<APP_START>>>"), response.contains("<<<APP_START>>>"),
response.contains("<<<TABLES_START>>>"), response.contains("<<<TABLES_START>>>"),
response.contains("<<<FILES_PLAN>>>"), response.contains("<<<FILES_PLAN>>>"),
@ -1976,7 +1976,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
} }
} }
} else { } else {
info!("[PHASE1_PARSE] TABLES_START not found, trying <<<TABLE:>>> delimiters..."); trace!(" TABLES_START not found, trying <<<TABLE:>>> delimiters...");
for table_match in response.match_indices("<<<TABLE:") { for table_match in response.match_indices("<<<TABLE:") {
let start = table_match.0; let start = table_match.0;
if let Some(rest) = response.get(start..) { if let Some(rest) = response.get(start..) {
@ -1984,7 +1984,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
if let Some(table_name) = rest.get(9..end_offset) { if let Some(table_name) = rest.get(9..end_offset) {
let table_name = table_name.trim(); let table_name = table_name.trim();
if !table_name.is_empty() { if !table_name.is_empty() {
info!("[PHASE1_PARSE] Found table from delimiter: {}", table_name); trace!(" Found table from delimiter: {}", table_name);
app.tables.push(LlmTable { app.tables.push(LlmTable {
name: table_name.to_string(), name: table_name.to_string(),
fields: Vec::new(), fields: Vec::new(),
@ -2019,13 +2019,13 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
|| filename.ends_with(".bas") || filename.ends_with(".bas")
|| filename.ends_with(".json")) || filename.ends_with(".json"))
{ {
info!("[PHASE1_PARSE] Adding file: {}", filename); trace!(" Adding file: {}", filename);
app.files.push(LlmFile { app.files.push(LlmFile {
filename, filename,
content: String::new(), // Content will be generated in Phase 2 content: String::new(), // Content will be generated in Phase 2
}); });
} else if !filename.is_empty() { } else if !filename.is_empty() {
info!("[PHASE1_PARSE] Skipped file (unknown ext): {}", filename); trace!(" Skipped file (unknown ext): {}", filename);
} }
} }
} }
@ -2041,7 +2041,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
if let Some(filename) = rest.get(8..end_offset) { if let Some(filename) = rest.get(8..end_offset) {
let filename = filename.trim(); let filename = filename.trim();
if !filename.is_empty() { if !filename.is_empty() {
info!("[PHASE1_PARSE] Found file from delimiter: {}", filename); trace!(" Found file from delimiter: {}", filename);
app.files.push(LlmFile { app.files.push(LlmFile {
filename: filename.to_string(), filename: filename.to_string(),
content: String::new(), content: String::new(),
@ -2078,7 +2078,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
} }
} }
} else { } else {
info!("[PHASE1_PARSE] TOOLS_PLAN not found, trying <<<TOOL:>>> delimiters..."); trace!(" TOOLS_PLAN not found, trying <<<TOOL:>>> delimiters...");
for tool_match in response.match_indices("<<<TOOL:") { for tool_match in response.match_indices("<<<TOOL:") {
let start = tool_match.0; let start = tool_match.0;
if let Some(rest) = response.get(start..) { if let Some(rest) = response.get(start..) {
@ -2091,7 +2091,7 @@ RESPOND ONLY WITH THE PLAN STRUCTURE. NO QUESTIONS."#
} else { } else {
format!("{}.bas", tool_name) format!("{}.bas", tool_name)
}; };
info!("[PHASE1_PARSE] Found tool from delimiter: {}", filename); trace!(" Found tool from delimiter: {}", filename);
app.tools.push(LlmFile { app.tools.push(LlmFile {
filename, filename,
content: String::new(), content: String::new(),
@ -2802,7 +2802,7 @@ NO QUESTIONS. JUST BUILD."#
&& !detected_tables.contains(&table_name.to_string()) && !detected_tables.contains(&table_name.to_string())
{ {
detected_tables.push(table_name.to_string()); detected_tables.push(table_name.to_string());
info!("[LLM_STREAM] Detected table: {table_name}"); info!("Detected table: {table_name}");
} }
} }
} }
@ -2819,7 +2819,7 @@ NO QUESTIONS. JUST BUILD."#
&& !detected_files.contains(&file_name.to_string()) && !detected_files.contains(&file_name.to_string())
{ {
detected_files.push(file_name.to_string()); detected_files.push(file_name.to_string());
info!("[LLM_STREAM] Detected file: {file_name}"); info!("Detected file: {file_name}");
} }
} }
} }
@ -2836,7 +2836,7 @@ NO QUESTIONS. JUST BUILD."#
&& !detected_tools.contains(&tool_name.to_string()) && !detected_tools.contains(&tool_name.to_string())
{ {
detected_tools.push(tool_name.to_string()); detected_tools.push(tool_name.to_string());
info!("[LLM_STREAM] Detected tool: {tool_name}"); info!("Detected tool: {tool_name}");
} }
} }
} }
@ -2865,7 +2865,7 @@ NO QUESTIONS. JUST BUILD."#
|| name.ends_with(".bas")) || name.ends_with(".bas"))
&& !detected_files.contains(&name.to_string()) { && !detected_files.contains(&name.to_string()) {
detected_files.push(name.to_string()); detected_files.push(name.to_string());
info!("[LLM_STREAM] Detected planned file: {name}"); info!("Detected planned file: {name}");
} }
} }
} }
@ -2894,7 +2894,7 @@ NO QUESTIONS. JUST BUILD."#
}; };
if !detected_tools.contains(&tool_name) { if !detected_tools.contains(&tool_name) {
detected_tools.push(tool_name.clone()); detected_tools.push(tool_name.clone());
info!("[LLM_STREAM] Detected planned tool: {tool_name}"); info!("Detected planned tool: {tool_name}");
} }
} }
} }
@ -2924,7 +2924,7 @@ NO QUESTIONS. JUST BUILD."#
}; };
if !detected_tools.contains(&sched_name) { if !detected_tools.contains(&sched_name) {
detected_tools.push(sched_name.clone()); detected_tools.push(sched_name.clone());
info!("[LLM_STREAM] Detected planned scheduler: {sched_name}"); info!("Detected planned scheduler: {sched_name}");
} }
} }
} }
@ -2962,7 +2962,7 @@ NO QUESTIONS. JUST BUILD."#
chars_received chars_received
) )
}; };
info!("[LLM_STREAM] Progress: {}", progress_msg); info!("Progress: {}", progress_msg);
let event = crate::core::shared::state::TaskProgressEvent::new( let event = crate::core::shared::state::TaskProgressEvent::new(
tid, tid,
"llm_generating", "llm_generating",
@ -3002,7 +3002,7 @@ NO QUESTIONS. JUST BUILD."#
} else { } else {
format!("AI complete: {} chars generated", full_response.len()) format!("AI complete: {} chars generated", full_response.len())
}; };
info!("[LLM_STREAM] {}", final_msg); info!("{}", final_msg);
let event = crate::core::shared::state::TaskProgressEvent::new( let event = crate::core::shared::state::TaskProgressEvent::new(
tid, tid,
"llm_complete", "llm_complete",

10
src/auto_task/autotask_api.rs
View file

@ -346,18 +346,18 @@ pub async fn create_and_execute_handler(
// Spawn background task to do the actual work // Spawn background task to do the actual work
let spawn_result = tokio::spawn(async move { let spawn_result = tokio::spawn(async move {
info!("[AUTOTASK] *** Background task STARTED for task_id={} ***", task_id_str); info!(" *** Background task STARTED for task_id={} ***", task_id_str);
// Use IntentClassifier to classify and process with task tracking // Use IntentClassifier to classify and process with task tracking
let classifier = IntentClassifier::new(state_clone.clone()); let classifier = IntentClassifier::new(state_clone.clone());
info!("[AUTOTASK] Calling classify_and_process_with_task_id for task_id={}", task_id_str); info!(" Calling classify_and_process_with_task_id for task_id={}", task_id_str);
let result = classifier let result = classifier
.classify_and_process_with_task_id(&intent, &session_clone, Some(task_id_str.clone())) .classify_and_process_with_task_id(&intent, &session_clone, Some(task_id_str.clone()))
.await; .await;
info!("[AUTOTASK] classify_and_process_with_task_id returned for task_id={}", task_id_str); info!(" classify_and_process_with_task_id returned for task_id={}", task_id_str);
match result { match result {
Ok(result) => { Ok(result) => {
@ -382,10 +382,10 @@ pub async fn create_and_execute_handler(
} }
}); });
info!("[AUTOTASK] Spawn result: {:?}", spawn_result); info!(" Spawn result: {:?}", spawn_result);
// Return immediately with task_id - client will poll for status // Return immediately with task_id - client will poll for status
info!("[AUTOTASK] Returning immediately with task_id={}", task_id); info!(" Returning immediately with task_id={}", task_id);
( (
StatusCode::ACCEPTED, StatusCode::ACCEPTED,
Json(CreateAndExecuteResponse { Json(CreateAndExecuteResponse {

4
src/auto_task/intent_classifier.rs
View file

@ -281,12 +281,12 @@ Respond with JSON only:
}}"# }}"#
); );
info!("[INTENT_CLASSIFIER] Starting LLM call for classification, prompt_len={} chars", prompt.len()); info!("Starting LLM call for classification, prompt_len={} chars", prompt.len());
let start = std::time::Instant::now(); let start = std::time::Instant::now();
let response = self.call_llm(&prompt, bot_id).await?; let response = self.call_llm(&prompt, bot_id).await?;
let elapsed = start.elapsed(); let elapsed = start.elapsed();
info!("[INTENT_CLASSIFIER] LLM classification completed in {:?}, response_len={} chars", elapsed, response.len()); info!("LLM classification completed in {:?}, response_len={} chars", elapsed, response.len());
trace!("LLM classification response: {}", &response[..response.len().min(500)]); trace!("LLM classification response: {}", &response[..response.len().min(500)]);
Self::parse_classification_response(&response, intent) Self::parse_classification_response(&response, intent)
} }

6
src/auto_task/mod.rs
View file

@ -179,17 +179,17 @@ async fn handle_task_progress_websocket(
match sender.send(Message::Text(json_str)).await { match sender.send(Message::Text(json_str)).await {
Ok(()) => { Ok(()) => {
if is_manifest { if is_manifest {
info!("[WS_HANDLER] manifest_update SENT successfully to WebSocket"); info!("manifest_update SENT successfully to WebSocket");
} }
} }
Err(e) => { Err(e) => {
error!("[WS_HANDLER] Failed to send to WebSocket: {:?}", e); error!("Failed to send to WebSocket: {:?}", e);
break; break;
} }
} }
} }
Err(e) => { Err(e) => {
error!("[WS_HANDLER] Failed to serialize event: {:?}", e); error!("Failed to serialize event: {:?}", e);
} }
} }
} }

4
src/basic/compiler/blocks/mail.rs
View file

@ -68,7 +68,7 @@ pub fn convert_mail_line_with_substitution(line: &str) -> String {
} }
} }
info!("[TOOL] Converted mail line: '{}' → '{}'", line, result); info!("Converted mail line: '{}' → '{}'", line, result);
result result
} }
@ -138,6 +138,6 @@ pub fn convert_mail_block(recipient: &str, lines: &[String]) -> String {
}; };
result.push_str(&format!("send_mail({}, \"{}\", {}, []);\n", recipient_expr, subject, body_expr)); result.push_str(&format!("send_mail({}, \"{}\", {}, []);\n", recipient_expr, subject, body_expr));
info!("[TOOL] Converted MAIL block → {}", result); info!("Converted MAIL block → {}", result);
result result
} }

8
src/basic/compiler/blocks/mod.rs
View file

@ -23,14 +23,14 @@ pub fn convert_begin_blocks(script: &str) -> String {
} }
if upper == "BEGIN TALK" { if upper == "BEGIN TALK" {
info!("[TOOL] Converting BEGIN TALK statement"); info!("Converting BEGIN TALK statement");
in_talk_block = true; in_talk_block = true;
talk_block_lines.clear(); talk_block_lines.clear();
continue; continue;
} }
if upper == "END TALK" { if upper == "END TALK" {
info!("[TOOL] Converting END TALK statement, processing {} lines", talk_block_lines.len()); info!("Converting END TALK statement, processing {} lines", talk_block_lines.len());
in_talk_block = false; in_talk_block = false;
let converted = convert_talk_block(&talk_block_lines); let converted = convert_talk_block(&talk_block_lines);
result.push_str(&converted); result.push_str(&converted);
@ -45,7 +45,7 @@ pub fn convert_begin_blocks(script: &str) -> String {
if upper.starts_with("BEGIN MAIL ") { if upper.starts_with("BEGIN MAIL ") {
let recipient = &trimmed[11..].trim(); let recipient = &trimmed[11..].trim();
info!("[TOOL] Converting BEGIN MAIL statement: recipient='{}'", recipient); info!("Converting BEGIN MAIL statement: recipient='{}'", recipient);
mail_recipient = recipient.to_string(); mail_recipient = recipient.to_string();
in_mail_block = true; in_mail_block = true;
mail_block_lines.clear(); mail_block_lines.clear();
@ -53,7 +53,7 @@ pub fn convert_begin_blocks(script: &str) -> String {
} }
if upper == "END MAIL" { if upper == "END MAIL" {
info!("[TOOL] Converting END MAIL statement, processing {} lines", mail_block_lines.len()); info!("Converting END MAIL statement, processing {} lines", mail_block_lines.len());
in_mail_block = false; in_mail_block = false;
let converted = convert_mail_block(&mail_recipient, &mail_block_lines); let converted = convert_mail_block(&mail_recipient, &mail_block_lines);
result.push_str(&converted); result.push_str(&converted);

2
src/basic/compiler/blocks/talk.rs
View file

@ -109,7 +109,7 @@ pub fn convert_talk_line_with_substitution(line: &str) -> String {
result = "TALK \"\"".to_string(); result = "TALK \"\"".to_string();
} }
info!("[TOOL] Converted TALK line: '{}' → '{}'", line, result); info!("Converted TALK line: '{}' → '{}'", line, result);
result result
} }

6
src/basic/compiler/mod.rs
View file

@ -676,7 +676,7 @@ impl BasicCompiler {
let table_name = table_name.trim_matches('"'); let table_name = table_name.trim_matches('"');
// Debug log to see what we're querying // Debug log to see what we're querying
log::info!("[SAVE] Converting SAVE for table: '{}' (original: '{}')", table_name, &parts[0]); log::info!("Converting SAVE for table: '{}' (original: '{}')", table_name, &parts[0]);
// Get column names from TABLE definition (preserves order from .bas file) // Get column names from TABLE definition (preserves order from .bas file)
let column_names = self.get_table_columns_for_save(table_name, bot_id)?; let column_names = self.get_table_columns_for_save(table_name, bot_id)?;
@ -685,7 +685,7 @@ impl BasicCompiler {
let values: Vec<&String> = parts.iter().skip(1).collect(); let values: Vec<&String> = parts.iter().skip(1).collect();
let mut map_pairs = Vec::new(); let mut map_pairs = Vec::new();
log::info!("[SAVE] Matching {} variables to {} columns", values.len(), column_names.len()); log::info!("Matching {} variables to {} columns", values.len(), column_names.len());
for value_var in values.iter() { for value_var in values.iter() {
// Find the column that matches this variable (case-insensitive) // Find the column that matches this variable (case-insensitive)
@ -694,7 +694,7 @@ impl BasicCompiler {
if let Some(column_name) = column_names.iter().find(|col| col.to_lowercase() == value_lower) { if let Some(column_name) = column_names.iter().find(|col| col.to_lowercase() == value_lower) {
map_pairs.push(format!("{}: {}", column_name, value_var)); map_pairs.push(format!("{}: {}", column_name, value_var));
} else { } else {
log::warn!("[SAVE] No matching column for variable '{}'", value_var); log::warn!("No matching column for variable '{}'", value_var);
} }
} }

6
src/basic/keywords/add_suggestion.rs
View file

@ -401,7 +401,7 @@ pub fn get_suggestions(
} }
} }
info!( info!(
"[SUGGESTIONS] Retrieved {} suggestions for session {}", "Retrieved {} suggestions for session {}",
suggestions.len(), suggestions.len(),
session_id session_id
); );
@ -413,7 +413,7 @@ pub fn get_suggestions(
// .arg(&redis_key) // .arg(&redis_key)
// .query(&mut conn); // .query(&mut conn);
// info!( // info!(
// "[SUGGESTIONS] Cleared {} suggestions from Redis for session {}", // "Cleared {} suggestions from Redis for session {}",
// suggestions.len(), // suggestions.len(),
// session_id // session_id
// ); // );
@ -422,7 +422,7 @@ pub fn get_suggestions(
Err(e) => error!("Failed to get suggestions from Redis: {}", e), Err(e) => error!("Failed to get suggestions from Redis: {}", e),
} }
} else { } else {
info!("[SUGGESTIONS] No cache configured, cannot retrieve suggestions"); info!("No cache configured, cannot retrieve suggestions");
} }
suggestions suggestions

10
src/basic/keywords/use_tool.rs
View file

@ -198,21 +198,13 @@ fn associate_tool_with_session(
tool_name: &str, tool_name: &str,
) -> Result<String, String> { ) -> Result<String, String> {
use crate::core::shared::models::schema::session_tool_associations; use crate::core::shared::models::schema::session_tool_associations;
use std::fs;
// Check if tool's .mcp.json file exists in work directory // Check if tool's .mcp.json file exists in work directory
// Use relative path from botserver binary location // Use relative path from botserver binary current directory
let gb_dir = std::env::current_dir() let gb_dir = std::env::current_dir()
.unwrap_or_else(|_| PathBuf::from(".")) .unwrap_or_else(|_| PathBuf::from("."))
.join("botserver-stack/data/system"); .join("botserver-stack/data/system");
// Ensure work directory exists (create if not)
let work_base = gb_dir.join("work");
if !work_base.exists() {
fs::create_dir_all(&work_base).map_err(|e| format!("Failed to create work directory {:?}: {}", work_base, e))?;
info!("Created work directory at: {:?}", work_base);
}
// Get bot name to construct the path // Get bot name to construct the path
let bot_name = get_bot_name_from_id(state, &user.bot_id)?; let bot_name = get_bot_name_from_id(state, &user.bot_id)?;
let work_path = Path::new(&gb_dir) let work_path = Path::new(&gb_dir)

48
src/basic/mod.rs
View file

@ -587,7 +587,7 @@ impl ScriptService {
.collect::<Vec<&str>>() .collect::<Vec<&str>>()
.join("\n"); .join("\n");
info!("[TOOL] Filtered tool metadata: {} -> {} chars", script.len(), executable_script.len()); info!("Filtered tool metadata: {} -> {} chars", script.len(), executable_script.len());
// Apply minimal preprocessing for tools (skip variable normalization to avoid breaking multi-line strings) // Apply minimal preprocessing for tools (skip variable normalization to avoid breaking multi-line strings)
let script = preprocess_switch(&executable_script); let script = preprocess_switch(&executable_script);
@ -597,7 +597,7 @@ impl ScriptService {
// let script = Self::convert_format_syntax(&script); // let script = Self::convert_format_syntax(&script);
// Skip normalize_variables_to_lowercase for tools - it breaks multi-line strings // Skip normalize_variables_to_lowercase for tools - it breaks multi-line strings
info!("[TOOL] Preprocessed tool script for Rhai compilation"); info!("Preprocessed tool script for Rhai compilation");
// Convert SAVE statements with field lists to map-based SAVE (simplified version for tools) // Convert SAVE statements with field lists to map-based SAVE (simplified version for tools)
let script = Self::convert_save_for_tools(&script); let script = Self::convert_save_for_tools(&script);
// Convert BEGIN TALK and BEGIN MAIL blocks to single calls // Convert BEGIN TALK and BEGIN MAIL blocks to single calls
@ -986,7 +986,7 @@ impl ScriptService {
}; };
result.push_str(&format!("send_mail({}, \"{}\", {}, []);\n", recipient_expr, subject, body_expr)); result.push_str(&format!("send_mail({}, \"{}\", {}, []);\n", recipient_expr, subject, body_expr));
log::info!("[TOOL] Converted MAIL block → {}", result); log::info!("Converted MAIL block → {}", result);
result result
} }
@ -1086,7 +1086,7 @@ impl ScriptService {
let mut mail_block_lines: Vec<String> = Vec::new(); let mut mail_block_lines: Vec<String> = Vec::new();
let mut in_line_continuation = false; let mut in_line_continuation = false;
log::info!("[TOOL] Converting IF/THEN syntax, input has {} lines", script.lines().count()); log::info!("Converting IF/THEN syntax, input has {} lines", script.lines().count());
for line in script.lines() { for line in script.lines() {
let trimmed = line.trim(); let trimmed = line.trim();
@ -1119,7 +1119,7 @@ impl ScriptService {
} else { } else {
condition.to_string() condition.to_string()
}; };
log::info!("[TOOL] Converting IF statement: condition='{}'", condition); log::info!("Converting IF statement: condition='{}'", condition);
result.push_str("if "); result.push_str("if ");
result.push_str(&condition); result.push_str(&condition);
result.push_str(" {\n"); result.push_str(" {\n");
@ -1129,7 +1129,7 @@ impl ScriptService {
// Handle ELSE // Handle ELSE
if upper == "ELSE" { if upper == "ELSE" {
log::info!("[TOOL] Converting ELSE statement"); log::info!("Converting ELSE statement");
result.push_str("} else {\n"); result.push_str("} else {\n");
continue; continue;
} }
@ -1152,7 +1152,7 @@ impl ScriptService {
} else { } else {
condition.to_string() condition.to_string()
}; };
log::info!("[TOOL] Converting ELSEIF statement: condition='{}'", condition); log::info!("Converting ELSEIF statement: condition='{}'", condition);
result.push_str("} else if "); result.push_str("} else if ");
result.push_str(&condition); result.push_str(&condition);
result.push_str(" {\n"); result.push_str(" {\n");
@ -1161,7 +1161,7 @@ impl ScriptService {
// Handle END IF // Handle END IF
if upper == "END IF" { if upper == "END IF" {
log::info!("[TOOL] Converting END IF statement"); log::info!("Converting END IF statement");
if if_stack.pop().is_some() { if if_stack.pop().is_some() {
result.push_str("}\n"); result.push_str("}\n");
} }
@ -1171,7 +1171,7 @@ impl ScriptService {
// Handle WITH ... END WITH (BASIC object creation) // Handle WITH ... END WITH (BASIC object creation)
if upper.starts_with("WITH ") { if upper.starts_with("WITH ") {
let object_name = &trimmed[5..].trim(); let object_name = &trimmed[5..].trim();
log::info!("[TOOL] Converting WITH statement: object='{}'", object_name); log::info!("Converting WITH statement: object='{}'", object_name);
// Convert WITH obj → let obj = #{ (start object literal) // Convert WITH obj → let obj = #{ (start object literal)
result.push_str("let "); result.push_str("let ");
result.push_str(object_name); result.push_str(object_name);
@ -1181,7 +1181,7 @@ impl ScriptService {
} }
if upper == "END WITH" { if upper == "END WITH" {
log::info!("[TOOL] Converting END WITH statement"); log::info!("Converting END WITH statement");
result.push_str("};\n"); result.push_str("};\n");
in_with_block = false; in_with_block = false;
continue; continue;
@ -1189,14 +1189,14 @@ impl ScriptService {
// Handle BEGIN TALK ... END TALK (multi-line TALK with ${} substitution) // Handle BEGIN TALK ... END TALK (multi-line TALK with ${} substitution)
if upper == "BEGIN TALK" { if upper == "BEGIN TALK" {
log::info!("[TOOL] Converting BEGIN TALK statement"); log::info!("Converting BEGIN TALK statement");
in_talk_block = true; in_talk_block = true;
talk_block_lines.clear(); talk_block_lines.clear();
continue; continue;
} }
if upper == "END TALK" { if upper == "END TALK" {
log::info!("[TOOL] Converting END TALK statement, processing {} lines", talk_block_lines.len()); log::info!("Converting END TALK statement, processing {} lines", talk_block_lines.len());
in_talk_block = false; in_talk_block = false;
// Split into multiple TALK statements to avoid expression complexity limit // Split into multiple TALK statements to avoid expression complexity limit
@ -1239,7 +1239,7 @@ impl ScriptService {
// Handle BEGIN MAIL ... END MAIL (multi-line email with ${} substitution) // Handle BEGIN MAIL ... END MAIL (multi-line email with ${} substitution)
if upper.starts_with("BEGIN MAIL ") { if upper.starts_with("BEGIN MAIL ") {
let recipient = &trimmed[11..].trim(); // Skip "BEGIN MAIL " let recipient = &trimmed[11..].trim(); // Skip "BEGIN MAIL "
log::info!("[TOOL] Converting BEGIN MAIL statement: recipient='{}'", recipient); log::info!("Converting BEGIN MAIL statement: recipient='{}'", recipient);
mail_recipient = recipient.to_string(); mail_recipient = recipient.to_string();
in_mail_block = true; in_mail_block = true;
mail_block_lines.clear(); mail_block_lines.clear();
@ -1247,7 +1247,7 @@ impl ScriptService {
} }
if upper == "END MAIL" { if upper == "END MAIL" {
log::info!("[TOOL] Converting END MAIL statement, processing {} lines", mail_block_lines.len()); log::info!("Converting END MAIL statement, processing {} lines", mail_block_lines.len());
in_mail_block = false; in_mail_block = false;
// Process the mail block and convert to SEND EMAIL // Process the mail block and convert to SEND EMAIL
@ -1287,11 +1287,11 @@ impl ScriptService {
// Handle SAVE table, field1, field2, ... → INSERT "table", #{field1: value1, field2: value2, ...} // Handle SAVE table, field1, field2, ... → INSERT "table", #{field1: value1, field2: value2, ...}
if upper.starts_with("SAVE") && upper.contains(',') { if upper.starts_with("SAVE") && upper.contains(',') {
log::info!("[TOOL] Processing SAVE line: '{}'", trimmed); log::info!("Processing SAVE line: '{}'", trimmed);
// Extract the part after "SAVE" // Extract the part after "SAVE"
let after_save = &trimmed[4..].trim(); // Skip "SAVE" let after_save = &trimmed[4..].trim(); // Skip "SAVE"
let parts: Vec<&str> = after_save.split(',').collect(); let parts: Vec<&str> = after_save.split(',').collect();
log::info!("[TOOL] SAVE parts: {:?}", parts); log::info!("SAVE parts: {:?}", parts);
if parts.len() >= 2 { if parts.len() >= 2 {
// First part is the table name (in quotes) // First part is the table name (in quotes)
@ -1301,7 +1301,7 @@ impl ScriptService {
if parts.len() == 2 { if parts.len() == 2 {
let object_name = parts[1].trim().trim_end_matches(';'); let object_name = parts[1].trim().trim_end_matches(';');
let converted = format!("INSERT \"{}\", {};\n", table, object_name); let converted = format!("INSERT \"{}\", {};\n", table, object_name);
log::info!("[TOOL] Converted SAVE to INSERT (old syntax): '{}'", converted); log::info!("Converted SAVE to INSERT (old syntax): '{}'", converted);
result.push_str(&converted); result.push_str(&converted);
continue; continue;
} }
@ -1310,7 +1310,7 @@ impl ScriptService {
// The runtime SAVE handler will match them to database columns by position // The runtime SAVE handler will match them to database columns by position
let values = parts[1..].join(", "); let values = parts[1..].join(", ");
let converted = format!("SAVE \"{}\", {};\n", table, values); let converted = format!("SAVE \"{}\", {};\n", table, values);
log::info!("[TOOL] Keeping SAVE syntax (modern): '{}'", converted); log::info!("Keeping SAVE syntax (modern): '{}'", converted);
result.push_str(&converted); result.push_str(&converted);
continue; continue;
} }
@ -1319,17 +1319,17 @@ impl ScriptService {
// Handle SEND EMAIL → send_mail (function call style) // Handle SEND EMAIL → send_mail (function call style)
// Syntax: SEND EMAIL to, subject, body → send_mail(to, subject, body, []) // Syntax: SEND EMAIL to, subject, body → send_mail(to, subject, body, [])
if upper.starts_with("SEND EMAIL") { if upper.starts_with("SEND EMAIL") {
log::info!("[TOOL] Processing SEND EMAIL line: '{}'", trimmed); log::info!("Processing SEND EMAIL line: '{}'", trimmed);
let after_send = &trimmed[11..].trim(); // Skip "SEND EMAIL " (10 chars + space = 11) let after_send = &trimmed[11..].trim(); // Skip "SEND EMAIL " (10 chars + space = 11)
let parts: Vec<&str> = after_send.split(',').collect(); let parts: Vec<&str> = after_send.split(',').collect();
log::info!("[TOOL] SEND EMAIL parts: {:?}", parts); log::info!("SEND EMAIL parts: {:?}", parts);
if parts.len() == 3 { if parts.len() == 3 {
let to = parts[0].trim(); let to = parts[0].trim();
let subject = parts[1].trim(); let subject = parts[1].trim();
let body = parts[2].trim().trim_end_matches(';'); let body = parts[2].trim().trim_end_matches(';');
// Convert to send_mail(to, subject, body, []) function call // Convert to send_mail(to, subject, body, []) function call
let converted = format!("send_mail({}, {}, {}, []);\n", to, subject, body); let converted = format!("send_mail({}, {}, {}, []);\n", to, subject, body);
log::info!("[TOOL] Converted SEND EMAIL to: '{}'", converted); log::info!("Converted SEND EMAIL to: '{}'", converted);
result.push_str(&converted); result.push_str(&converted);
continue; continue;
} }
@ -1397,7 +1397,7 @@ impl ScriptService {
} }
} }
log::info!("[TOOL] IF/THEN conversion complete, output has {} lines", result.lines().count()); log::info!("IF/THEN conversion complete, output has {} lines", result.lines().count());
// Convert BASIC <> (not equal) to Rhai != globally // Convert BASIC <> (not equal) to Rhai != globally
@ -1417,7 +1417,7 @@ impl ScriptService {
let lines: Vec<&str> = script.lines().collect(); let lines: Vec<&str> = script.lines().collect();
let mut i = 0; let mut i = 0;
log::info!("[TOOL] Converting SELECT/CASE syntax to if-else chains"); log::info!("Converting SELECT/CASE syntax to if-else chains");
// Helper function to strip 'let ' from the beginning of a line // Helper function to strip 'let ' from the beginning of a line
// This is needed because convert_if_then_syntax adds 'let' to all assignments, // This is needed because convert_if_then_syntax adds 'let' to all assignments,
@ -1441,7 +1441,7 @@ impl ScriptService {
if upper.starts_with("SELECT ") && !upper.contains(" THEN") { if upper.starts_with("SELECT ") && !upper.contains(" THEN") {
// Extract the variable being selected // Extract the variable being selected
let select_var = trimmed[7..].trim(); // Skip "SELECT " let select_var = trimmed[7..].trim(); // Skip "SELECT "
log::info!("[TOOL] Converting SELECT statement for variable: '{}'", select_var); log::info!("Converting SELECT statement for variable: '{}'", select_var);
// Skip the SELECT line // Skip the SELECT line
i += 1; i += 1;

85
src/core/bot/mod.rs
View file

@ -440,9 +440,6 @@ impl BotOrchestrator {
let config_manager = ConfigManager::new(state_clone.conn.clone()); let config_manager = ConfigManager::new(state_clone.conn.clone());
// DEBUG: Log which bot we're getting config for
info!("[CONFIG_TRACE] Getting LLM config for bot_id: {}", session.bot_id);
// For local LLM server, use the actual model name // For local LLM server, use the actual model name
// Default to DeepSeek model if not configured // Default to DeepSeek model if not configured
let model = config_manager let model = config_manager
@ -453,12 +450,6 @@ impl BotOrchestrator {
.get_config(&session.bot_id, "llm-key", Some("")) .get_config(&session.bot_id, "llm-key", Some(""))
.unwrap_or_default(); .unwrap_or_default();
// DEBUG: Log the exact config values retrieved
info!("[CONFIG_TRACE] Model: '{}'", model);
info!("[CONFIG_TRACE] API Key: '{}' ({} chars)", key, key.len());
info!("[CONFIG_TRACE] API Key first 10 chars: '{}'", &key.chars().take(10).collect::<String>());
info!("[CONFIG_TRACE] API Key last 10 chars: '{}'", &key.chars().rev().take(10).collect::<String>());
Ok((session, context_data, history, model, key)) Ok((session, context_data, history, model, key))
}, },
) )
@ -508,12 +499,10 @@ impl BotOrchestrator {
let data_dir = "/opt/gbo/data"; let data_dir = "/opt/gbo/data";
let start_script_path = format!("{}/{}.gbai/{}.gbdialog/start.bas", data_dir, bot_name_for_context, bot_name_for_context); let start_script_path = format!("{}/{}.gbai/{}.gbdialog/start.bas", data_dir, bot_name_for_context, bot_name_for_context);
info!("[START_BAS] Executing start.bas for session {} at: {}", actual_session_id, start_script_path); trace!("Executing start.bas for session {} at: {}", actual_session_id, start_script_path);
if let Ok(metadata) = tokio::fs::metadata(&start_script_path).await { if let Ok(metadata) = tokio::fs::metadata(&start_script_path).await {
if metadata.is_file() { if metadata.is_file() {
info!("[START_BAS] Found start.bas, executing for session {}", actual_session_id);
if let Ok(start_script) = tokio::fs::read_to_string(&start_script_path).await { if let Ok(start_script) = tokio::fs::read_to_string(&start_script_path).await {
let state_clone = self.state.clone(); let state_clone = self.state.clone();
let actual_session_id_for_task = session.id; let actual_session_id_for_task = session.id;
@ -551,7 +540,7 @@ impl BotOrchestrator {
match result { match result {
Ok(Ok(())) => { Ok(Ok(())) => {
info!("[START_BAS] start.bas completed successfully for session {}", actual_session_id); trace!("start.bas completed successfully for session {}", actual_session_id);
// Mark start.bas as executed for this session to prevent re-running // Mark start.bas as executed for this session to prevent re-running
if let Some(cache) = &self.state.cache { if let Some(cache) = &self.state.cache {
@ -563,15 +552,14 @@ impl BotOrchestrator {
.arg("86400") // Expire after 24 hours .arg("86400") // Expire after 24 hours
.query_async(&mut conn) .query_async(&mut conn)
.await; .await;
info!("[START_BAS] Marked start.bas as executed for session {}", actual_session_id);
} }
} }
} }
Ok(Err(e)) => { Ok(Err(e)) => {
error!("[START_BAS] start.bas error for session {}: {}", actual_session_id, e); error!("start.bas error for session {}: {}", actual_session_id, e);
} }
Err(e) => { Err(e) => {
error!("[START_BAS] start.bas task error for session {}: {}", actual_session_id, e); error!("start.bas task error for session {}: {}", actual_session_id, e);
} }
} }
} }
@ -613,12 +601,7 @@ impl BotOrchestrator {
})); }));
} }
// DEBUG: Log messages before sending to LLM
info!("[LLM_CALL] Messages before LLM: {}", serde_json::to_string_pretty(&messages).unwrap_or_default());
info!("[LLM_CALL] message_content: '{}'", message_content);
let (stream_tx, mut stream_rx) = mpsc::channel::<String>(100); let (stream_tx, mut stream_rx) = mpsc::channel::<String>(100);
info!("[STREAM_SETUP] Channel created, starting LLM stream");
let llm = self.state.llm_provider.clone(); let llm = self.state.llm_provider.clone();
let model_clone = model.clone(); let model_clone = model.clone();
@ -629,15 +612,13 @@ impl BotOrchestrator {
let tools_for_llm = match session_tools { let tools_for_llm = match session_tools {
Ok(tools) => { Ok(tools) => {
if !tools.is_empty() { if !tools.is_empty() {
info!("[TOOLS] Loaded {} tools for session {}", tools.len(), session.id);
Some(tools) Some(tools)
} else { } else {
info!("[TOOLS] No tools associated with session {}", session.id);
None None
} }
} }
Err(e) => { Err(e) => {
warn!("[TOOLS] Failed to load session tools: {}", e); warn!("Failed to load session tools: {}", e);
None None
} }
}; };
@ -645,24 +626,13 @@ impl BotOrchestrator {
// Clone messages for the async task // Clone messages for the async task
let messages_clone = messages.clone(); let messages_clone = messages.clone();
// DEBUG: Log exact values being passed to LLM
info!("[LLM_CALL] Calling generate_stream with:");
info!("[LLM_CALL] Model: '{}'", model_clone);
info!("[LLM_CALL] Key length: {} chars", key_clone.len());
info!("[LLM_CALL] Key preview: '{}...{}'",
&key_clone.chars().take(8).collect::<String>(),
&key_clone.chars().rev().take(8).collect::<String>()
);
tokio::spawn(async move { tokio::spawn(async move {
info!("[SPAWN_TASK] LLM stream task started");
if let Err(e) = llm if let Err(e) = llm
.generate_stream("", &messages_clone, stream_tx, &model_clone, &key_clone, tools_for_llm.as_ref()) .generate_stream("", &messages_clone, stream_tx, &model_clone, &key_clone, tools_for_llm.as_ref())
.await .await
{ {
error!("LLM streaming error: {}", e); error!("LLM streaming error: {}", e);
} }
info!("[SPAWN_TASK] LLM stream task completed");
}); });
let mut full_response = String::new(); let mut full_response = String::new();
@ -673,9 +643,6 @@ impl BotOrchestrator {
let mut tool_was_executed = false; // Track if a tool was executed to avoid duplicate final message let mut tool_was_executed = false; // Track if a tool was executed to avoid duplicate final message
let handler = llm_models::get_handler(&model); let handler = llm_models::get_handler(&model);
info!("[STREAM_START] Entering stream processing loop for model: {}", model);
info!("[STREAM_START] About to enter while loop, stream_rx is valid");
trace!("Using model handler for {}", model); trace!("Using model handler for {}", model);
#[cfg(feature = "nvidia")] #[cfg(feature = "nvidia")]
@ -700,7 +667,6 @@ impl BotOrchestrator {
} }
while let Some(chunk) = stream_rx.recv().await { while let Some(chunk) = stream_rx.recv().await {
info!("[STREAM_DEBUG] Received chunk: '{}', len: {}", chunk, chunk.len());
trace!("Received LLM chunk: {:?}", chunk); trace!("Received LLM chunk: {:?}", chunk);
// ===== GENERIC TOOL EXECUTION ===== // ===== GENERIC TOOL EXECUTION =====
@ -724,7 +690,6 @@ impl BotOrchestrator {
// Send the part before { as regular content // Send the part before { as regular content
let regular_part = &chunk[..pos]; let regular_part = &chunk[..pos];
if !regular_part.trim().is_empty() { if !regular_part.trim().is_empty() {
info!("[STREAM_CONTENT] Sending regular part before JSON: '{}', len: {}", regular_part, regular_part.len());
full_response.push_str(regular_part); full_response.push_str(regular_part);
let response = BotResponse { let response = BotResponse {
@ -774,11 +739,6 @@ impl BotOrchestrator {
}; };
if let Some(tc) = tool_call { if let Some(tc) = tool_call {
info!(
"[TOOL_CALL] Detected tool '{}' from LLM, executing...",
tc.tool_name
);
let execution_result = ToolExecutor::execute_tool_call( let execution_result = ToolExecutor::execute_tool_call(
&self.state, &self.state,
&bot_name_for_context, &bot_name_for_context,
@ -862,7 +822,6 @@ impl BotOrchestrator {
// Increased limit to 50000 to handle large tool calls with many parameters // Increased limit to 50000 to handle large tool calls with many parameters
if tool_call_buffer.len() > 50000 { if tool_call_buffer.len() > 50000 {
// Flush accumulated content to client since it's too large to be a tool call // Flush accumulated content to client since it's too large to be a tool call
info!("[TOOL_EXEC] Flushing tool_call_buffer (too large, assuming not a tool call)");
full_response.push_str(&tool_call_buffer); full_response.push_str(&tool_call_buffer);
let response = BotResponse { let response = BotResponse {
@ -934,13 +893,9 @@ impl BotOrchestrator {
if in_analysis && handler.is_analysis_complete(&analysis_buffer) { if in_analysis && handler.is_analysis_complete(&analysis_buffer) {
in_analysis = false; in_analysis = false;
info!( trace!("Detected end of thinking for model {}", model);
"[ANALYSIS] Detected end of thinking for model {}. Buffer: '{}'",
model, analysis_buffer
);
let processed = handler.process_content(&analysis_buffer); let processed = handler.process_content(&analysis_buffer);
info!("[ANALYSIS] Processed content: '{}'", processed);
if !processed.is_empty() { if !processed.is_empty() {
full_response.push_str(&processed); full_response.push_str(&processed);
@ -975,7 +930,6 @@ impl BotOrchestrator {
} }
if !in_analysis { if !in_analysis {
info!("[STREAM_CONTENT] Sending chunk: '{}', len: {}", chunk, chunk.len());
full_response.push_str(&chunk); full_response.push_str(&chunk);
let response = BotResponse { let response = BotResponse {
@ -1000,8 +954,6 @@ impl BotOrchestrator {
} }
} }
info!("[STREAM_END] While loop exited. full_response length: {}", full_response.len());
let state_for_save = self.state.clone(); let state_for_save = self.state.clone();
let full_response_clone = full_response.clone(); let full_response_clone = full_response.clone();
tokio::task::spawn_blocking( tokio::task::spawn_blocking(
@ -1366,18 +1318,14 @@ async fn handle_websocket(
while let Some(Ok(msg)) = receiver.next().await { while let Some(Ok(msg)) = receiver.next().await {
match msg { match msg {
Message::Text(text) => { Message::Text(text) => {
info!("Received WebSocket message: {}", text);
if let Ok(user_msg) = serde_json::from_str::<UserMessage>(&text) { if let Ok(user_msg) = serde_json::from_str::<UserMessage>(&text) {
let orchestrator = BotOrchestrator::new(state_clone.clone()); let orchestrator = BotOrchestrator::new(state_clone.clone());
info!("[WS_DEBUG] Looking up response channel for session: {}", session_id);
if let Some(tx_clone) = state_clone if let Some(tx_clone) = state_clone
.response_channels .response_channels
.lock() .lock()
.await .await
.get(&session_id.to_string()) .get(&session_id.to_string())
{ {
info!("[WS_DEBUG] Response channel found, calling stream_response");
// Ensure session exists - create if not // Ensure session exists - create if not
let session_result = { let session_result = {
let mut sm = state_clone.session_manager.lock().await; let mut sm = state_clone.session_manager.lock().await;
@ -1385,27 +1333,20 @@ async fn handle_websocket(
}; };
let session = match session_result { let session = match session_result {
Ok(Some(sess)) => { Ok(Some(sess)) => sess,
info!("[WS_DEBUG] Session exists: {}", session_id);
sess
}
Ok(None) => { Ok(None) => {
info!("[WS_DEBUG] Session not found, creating via session manager");
// Use session manager to create session (will generate new UUID) // Use session manager to create session (will generate new UUID)
let mut sm = state_clone.session_manager.lock().await; let mut sm = state_clone.session_manager.lock().await;
match sm.create_session(user_id, bot_id, "WebSocket Chat") { match sm.create_session(user_id, bot_id, "WebSocket Chat") {
Ok(new_session) => { Ok(new_session) => new_session,
info!("[WS_DEBUG] Session created: {} (note: different from WebSocket session_id)", new_session.id);
new_session
}
Err(e) => { Err(e) => {
error!("[WS_DEBUG] Failed to create session: {}", e); error!("Failed to create session: {}", e);
continue; continue;
} }
} }
} }
Err(e) => { Err(e) => {
error!("[WS_DEBUG] Error getting session: {}", e); error!("Error getting session: {}", e);
continue; continue;
} }
}; };
@ -1424,14 +1365,14 @@ async fn handle_websocket(
error!("Failed to stream response: {}", e); error!("Failed to stream response: {}", e);
} }
} else { } else {
warn!("[WS_DEBUG] Response channel NOT found for session: {}", session_id); warn!("Response channel NOT found for session: {}", session_id);
} }
} else { } else {
warn!("[WS_DEBUG] Failed to parse UserMessage from: {}", text); warn!("Failed to parse UserMessage from: {}", text);
} }
} }
Message::Close(_) => { Message::Close(_) => {
info!("WebSocket close message received"); trace!("WebSocket close message received");
break; break;
} }
_ => {} _ => {}

8
src/core/bot/tool_executor.rs
View file

@ -1,6 +1,6 @@
/// Generic tool executor for LLM tool calls /// Generic tool executor for LLM tool calls
/// Works across all LLM providers (GLM, OpenAI, Claude, etc.) /// Works across all LLM providers (GLM, OpenAI, Claude, etc.)
use log::{error, info, warn}; use log::{error, info, trace, warn};
use serde_json::Value; use serde_json::Value;
// use std::collections::HashMap; // use std::collections::HashMap;
use std::fs::OpenOptions; use std::fs::OpenOptions;
@ -60,7 +60,7 @@ impl ToolExecutor {
} }
// Also log to system logger // Also log to system logger
error!("[TOOL_ERROR] Bot: {}, Tool: {}, Error: {}", bot_name, tool_name, error_msg); error!("Tool error in {} (bot: {}): {}", tool_name, bot_name, error_msg);
} }
/// Convert internal errors to user-friendly messages for browser /// Convert internal errors to user-friendly messages for browser
@ -278,7 +278,7 @@ 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!("[TOOL_EXEC] Failed to set variable '{}': {}", key, e); warn!("Failed to set variable '{}': {}", key, e);
} }
} }
} }
@ -302,7 +302,7 @@ impl ToolExecutor {
// Run the script // Run the script
match script_service.run(&ast) { match script_service.run(&ast) {
Ok(result) => { Ok(result) => {
info!("[TOOL_EXEC] Tool '{}' executed successfully", tool_name); trace!("Tool '{}' executed successfully", tool_name);
// Convert result to string // Convert result to string
let result_str = result.to_string(); let result_str = result.to_string();

38
src/core/kb/embedding_generator.rs
View file

@ -20,7 +20,7 @@ pub fn is_embedding_server_ready() -> bool {
pub fn set_embedding_server_ready(ready: bool) { pub fn set_embedding_server_ready(ready: bool) {
EMBEDDING_SERVER_READY.store(ready, Ordering::SeqCst); EMBEDDING_SERVER_READY.store(ready, Ordering::SeqCst);
if ready { if ready {
info!("[EMBEDDING] Embedding server marked as ready"); info!("Embedding server marked as ready");
} }
} }
@ -285,13 +285,13 @@ impl KbEmbeddingGenerator {
is_healthy is_healthy
} }
_ => { _ => {
warn!("[EMBEDDING] Health check failed: {}", e); warn!("Health check failed: {}", e);
false false
} }
} }
} }
Err(_) => { Err(_) => {
warn!("[EMBEDDING] Health check timed out"); warn!("Health check timed out");
false false
} }
} }
@ -301,18 +301,18 @@ impl KbEmbeddingGenerator {
let start = std::time::Instant::now(); let start = std::time::Instant::now();
let max_wait = Duration::from_secs(max_wait_secs); let max_wait = Duration::from_secs(max_wait_secs);
info!("[EMBEDDING] Waiting for embedding server at {} (max {}s)...", info!("Waiting for embedding server at {} (max {}s)...",
self.config.embedding_url, max_wait_secs); self.config.embedding_url, max_wait_secs);
while start.elapsed() < max_wait { while start.elapsed() < max_wait {
if self.check_health().await { if self.check_health().await {
info!("[EMBEDDING] Embedding server is ready after {:?}", start.elapsed()); info!("Embedding server is ready after {:?}", start.elapsed());
return true; return true;
} }
tokio::time::sleep(Duration::from_secs(2)).await; tokio::time::sleep(Duration::from_secs(2)).await;
} }
warn!("[EMBEDDING] Embedding server not available after {}s", max_wait_secs); warn!("Embedding server not available after {}s", max_wait_secs);
false false
} }
@ -325,7 +325,7 @@ impl KbEmbeddingGenerator {
} }
if !is_embedding_server_ready() { if !is_embedding_server_ready() {
info!("[EMBEDDING] Server not marked ready, checking health..."); trace!("Server not marked ready, checking health...");
if !self.wait_for_server(30).await { if !self.wait_for_server(30).await {
return Err(anyhow::anyhow!( return Err(anyhow::anyhow!(
"Embedding server not available at {}. Skipping embedding generation.", "Embedding server not available at {}. Skipping embedding generation.",
@ -335,7 +335,7 @@ impl KbEmbeddingGenerator {
} }
let start_mem = MemoryStats::current(); let start_mem = MemoryStats::current();
trace!("[EMBEDDING] Generating embeddings for {} chunks, RSS={}", trace!("Generating embeddings for {} chunks, RSS={}",
chunks.len(), MemoryStats::format_bytes(start_mem.rss_bytes)); chunks.len(), MemoryStats::format_bytes(start_mem.rss_bytes));
let mut results = Vec::with_capacity(chunks.len()); let mut results = Vec::with_capacity(chunks.len());
@ -343,7 +343,7 @@ impl KbEmbeddingGenerator {
for (batch_num, batch) in chunks.chunks(self.config.batch_size).enumerate() { for (batch_num, batch) in chunks.chunks(self.config.batch_size).enumerate() {
let batch_start = MemoryStats::current(); let batch_start = MemoryStats::current();
trace!("[EMBEDDING] Processing batch {}/{} ({} items), RSS={}", trace!("Processing batch {}/{} ({} items), RSS={}",
batch_num + 1, batch_num + 1,
total_batches, total_batches,
batch.len(), batch.len(),
@ -355,11 +355,11 @@ impl KbEmbeddingGenerator {
).await { ).await {
Ok(Ok(embeddings)) => embeddings, Ok(Ok(embeddings)) => embeddings,
Ok(Err(e)) => { Ok(Err(e)) => {
warn!("[EMBEDDING] Batch {} failed: {}", batch_num + 1, e); warn!("Batch {} failed: {}", batch_num + 1, e);
break; break;
} }
Err(_) => { Err(_) => {
warn!("[EMBEDDING] Batch {} timed out after {}s", warn!("Batch {} timed out after {}s",
batch_num + 1, self.config.timeout_seconds); batch_num + 1, self.config.timeout_seconds);
break; break;
} }
@ -367,14 +367,14 @@ impl KbEmbeddingGenerator {
let batch_end = MemoryStats::current(); let batch_end = MemoryStats::current();
let delta = batch_end.rss_bytes.saturating_sub(batch_start.rss_bytes); let delta = batch_end.rss_bytes.saturating_sub(batch_start.rss_bytes);
trace!("[EMBEDDING] Batch {} complete: {} embeddings, RSS={} (delta={})", trace!("Batch {} complete: {} embeddings, RSS={} (delta={})",
batch_num + 1, batch_num + 1,
batch_embeddings.len(), batch_embeddings.len(),
MemoryStats::format_bytes(batch_end.rss_bytes), MemoryStats::format_bytes(batch_end.rss_bytes),
MemoryStats::format_bytes(delta)); MemoryStats::format_bytes(delta));
if delta > 100 * 1024 * 1024 { if delta > 100 * 1024 * 1024 {
warn!("[EMBEDDING] Excessive memory growth detected ({}), stopping early", warn!("Excessive memory growth detected ({}), stopping early",
MemoryStats::format_bytes(delta)); MemoryStats::format_bytes(delta));
for (chunk, embedding) in batch.iter().zip(batch_embeddings.iter()) { for (chunk, embedding) in batch.iter().zip(batch_embeddings.iter()) {
results.push((chunk.clone(), embedding.clone())); results.push((chunk.clone(), embedding.clone()));
@ -392,7 +392,7 @@ impl KbEmbeddingGenerator {
} }
let end_mem = MemoryStats::current(); let end_mem = MemoryStats::current();
trace!("[EMBEDDING] Generated {} embeddings, RSS={} (total delta={})", trace!("Generated {} embeddings, RSS={} (total delta={})",
results.len(), results.len(),
MemoryStats::format_bytes(end_mem.rss_bytes), MemoryStats::format_bytes(end_mem.rss_bytes),
MemoryStats::format_bytes(end_mem.rss_bytes.saturating_sub(start_mem.rss_bytes))); MemoryStats::format_bytes(end_mem.rss_bytes.saturating_sub(start_mem.rss_bytes)));
@ -408,16 +408,16 @@ impl KbEmbeddingGenerator {
let texts: Vec<String> = chunks.iter().map(|c| c.content.clone()).collect(); let texts: Vec<String> = chunks.iter().map(|c| c.content.clone()).collect();
let total_chars: usize = texts.iter().map(|t| t.len()).sum(); let total_chars: usize = texts.iter().map(|t| t.len()).sum();
info!("[EMBEDDING] generate_batch_embeddings: {} texts, {} total chars", trace!("generate_batch_embeddings: {} texts, {} total chars",
texts.len(), total_chars); texts.len(), total_chars);
match self.generate_local_embeddings(&texts).await { match self.generate_local_embeddings(&texts).await {
Ok(embeddings) => { Ok(embeddings) => {
info!("[EMBEDDING] Local embeddings succeeded: {} vectors", embeddings.len()); trace!("Local embeddings succeeded: {} vectors", embeddings.len());
Ok(embeddings) Ok(embeddings)
} }
Err(e) => { Err(e) => {
warn!("[EMBEDDING] Local embedding service failed: {}", e); warn!("Local embedding service failed: {}", e);
Err(e) Err(e)
} }
} }
@ -437,7 +437,7 @@ impl KbEmbeddingGenerator {
let request_size = serde_json::to_string(&request) let request_size = serde_json::to_string(&request)
.map(|s| s.len()) .map(|s| s.len())
.unwrap_or(0); .unwrap_or(0);
info!("[EMBEDDING] Sending request to {} (size: {} bytes)", trace!("Sending request to {} (size: {} bytes)",
self.config.embedding_url, request_size); self.config.embedding_url, request_size);
let response = self let response = self
@ -462,7 +462,7 @@ impl KbEmbeddingGenerator {
let response_bytes = response.bytes().await let response_bytes = response.bytes().await
.context("Failed to read embedding response bytes")?; .context("Failed to read embedding response bytes")?;
info!("[EMBEDDING] Received response: {} bytes", response_bytes.len()); trace!("Received response: {} bytes", response_bytes.len());
if response_bytes.len() > 50 * 1024 * 1024 { if response_bytes.len() > 50 * 1024 * 1024 {
return Err(anyhow::anyhow!( return Err(anyhow::anyhow!(

22
src/core/kb/kb_indexer.rs
View file

@ -126,7 +126,7 @@ impl KbIndexer {
log_jemalloc_stats(); log_jemalloc_stats();
if !is_embedding_server_ready() { if !is_embedding_server_ready() {
info!("[KB_INDEXER] Embedding server not ready yet, waiting up to 60s..."); info!("Embedding server not ready yet, waiting up to 60s...");
if !self.embedding_generator.wait_for_server(60).await { if !self.embedding_generator.wait_for_server(60).await {
warn!( warn!(
"Embedding server is not available. KB indexing skipped. \ "Embedding server is not available. KB indexing skipped. \
@ -155,13 +155,13 @@ impl KbIndexer {
self.ensure_collection_exists(&collection_name).await?; self.ensure_collection_exists(&collection_name).await?;
let before_docs = MemoryStats::current(); let before_docs = MemoryStats::current();
trace!("[KB_INDEXER] Before process_kb_folder RSS={}", trace!("Before process_kb_folder RSS={}",
MemoryStats::format_bytes(before_docs.rss_bytes)); MemoryStats::format_bytes(before_docs.rss_bytes));
let documents = self.document_processor.process_kb_folder(kb_path).await?; let documents = self.document_processor.process_kb_folder(kb_path).await?;
let after_docs = MemoryStats::current(); let after_docs = MemoryStats::current();
trace!("[KB_INDEXER] After process_kb_folder: {} documents, RSS={} (delta={})", trace!("After process_kb_folder: {} documents, RSS={} (delta={})",
documents.len(), documents.len(),
MemoryStats::format_bytes(after_docs.rss_bytes), MemoryStats::format_bytes(after_docs.rss_bytes),
MemoryStats::format_bytes(after_docs.rss_bytes.saturating_sub(before_docs.rss_bytes))); MemoryStats::format_bytes(after_docs.rss_bytes.saturating_sub(before_docs.rss_bytes)));
@ -176,7 +176,7 @@ impl KbIndexer {
for (doc_path, chunks) in doc_iter { for (doc_path, chunks) in doc_iter {
if chunks.is_empty() { if chunks.is_empty() {
debug!("[KB_INDEXER] Skipping document with no chunks: {}", doc_path); debug!("Skipping document with no chunks: {}", doc_path);
continue; continue;
} }
@ -198,7 +198,7 @@ impl KbIndexer {
// Memory pressure check - more aggressive // Memory pressure check - more aggressive
let current_mem = MemoryStats::current(); let current_mem = MemoryStats::current();
if current_mem.rss_bytes > 1_500_000_000 { // 1.5GB threshold (reduced) if current_mem.rss_bytes > 1_500_000_000 { // 1.5GB threshold (reduced)
warn!("[KB_INDEXER] High memory usage detected: {}, forcing cleanup", warn!("High memory usage detected: {}, forcing cleanup",
MemoryStats::format_bytes(current_mem.rss_bytes)); MemoryStats::format_bytes(current_mem.rss_bytes));
// Force garbage collection hint // Force garbage collection hint
@ -220,7 +220,7 @@ impl KbIndexer {
self.update_collection_metadata(&collection_name, bot_name, kb_name, total_chunks)?; self.update_collection_metadata(&collection_name, bot_name, kb_name, total_chunks)?;
let end_mem = MemoryStats::current(); let end_mem = MemoryStats::current();
trace!("[KB_INDEXER] Indexing complete: {} docs, {} chunks, RSS={} (total delta={})", trace!("Indexing complete: {} docs, {} chunks, RSS={} (total delta={})",
indexed_documents, total_chunks, indexed_documents, total_chunks,
MemoryStats::format_bytes(end_mem.rss_bytes), MemoryStats::format_bytes(end_mem.rss_bytes),
MemoryStats::format_bytes(end_mem.rss_bytes.saturating_sub(start_mem.rss_bytes))); MemoryStats::format_bytes(end_mem.rss_bytes.saturating_sub(start_mem.rss_bytes)));
@ -245,7 +245,7 @@ impl KbIndexer {
while let Some((doc_path, chunks)) = batch_docs.pop() { while let Some((doc_path, chunks)) = batch_docs.pop() {
let before_embed = MemoryStats::current(); let before_embed = MemoryStats::current();
trace!( trace!(
"[KB_INDEXER] Processing document: {} ({} chunks) RSS={}", "Processing document: {} ({} chunks) RSS={}",
doc_path, doc_path,
chunks.len(), chunks.len(),
MemoryStats::format_bytes(before_embed.rss_bytes) MemoryStats::format_bytes(before_embed.rss_bytes)
@ -253,7 +253,7 @@ impl KbIndexer {
// Re-validate embedding server is still available // Re-validate embedding server is still available
if !is_embedding_server_ready() { if !is_embedding_server_ready() {
warn!("[KB_INDEXER] Embedding server became unavailable during indexing, aborting batch"); warn!("Embedding server became unavailable during indexing, aborting batch");
return Err(anyhow::anyhow!( return Err(anyhow::anyhow!(
"Embedding server became unavailable during KB indexing. Processed {} documents before failure.", "Embedding server became unavailable during KB indexing. Processed {} documents before failure.",
processed_count processed_count
@ -265,7 +265,7 @@ impl KbIndexer {
let chunk_batches = chunks.chunks(CHUNK_BATCH_SIZE); let chunk_batches = chunks.chunks(CHUNK_BATCH_SIZE);
for chunk_batch in chunk_batches { for chunk_batch in chunk_batches {
trace!("[KB_INDEXER] Processing chunk batch of {} chunks", chunk_batch.len()); trace!("Processing chunk batch of {} chunks", chunk_batch.len());
let embeddings = match self let embeddings = match self
.embedding_generator .embedding_generator
@ -274,7 +274,7 @@ impl KbIndexer {
{ {
Ok(emb) => emb, Ok(emb) => emb,
Err(e) => { Err(e) => {
warn!("[KB_INDEXER] Embedding generation failed for {}: {}", doc_path, e); warn!("Embedding generation failed for {}: {}", doc_path, e);
break; // Skip to next document break; // Skip to next document
} }
}; };
@ -287,7 +287,7 @@ impl KbIndexer {
} }
let after_embed = MemoryStats::current(); let after_embed = MemoryStats::current();
trace!("[KB_INDEXER] After processing document: RSS={} (delta={})", trace!("After processing document: RSS={} (delta={})",
MemoryStats::format_bytes(after_embed.rss_bytes), MemoryStats::format_bytes(after_embed.rss_bytes),
MemoryStats::format_bytes(after_embed.rss_bytes.saturating_sub(before_embed.rss_bytes))); MemoryStats::format_bytes(after_embed.rss_bytes.saturating_sub(before_embed.rss_bytes)));

32
src/core/kb/website_crawler_service.rs
View file

@ -4,7 +4,7 @@ use crate::core::kb::KnowledgeBaseManager;
use crate::core::shared::state::AppState; use crate::core::shared::state::AppState;
use crate::core::shared::utils::DbPool; use crate::core::shared::utils::DbPool;
use diesel::prelude::*; use diesel::prelude::*;
use log::{error, info, warn}; use log::{error, trace, warn};
use regex; use regex;
use std::collections::HashSet; use std::collections::HashSet;
use std::sync::Arc; use std::sync::Arc;
@ -35,7 +35,7 @@ impl WebsiteCrawlerService {
let service = Arc::clone(&self); let service = Arc::clone(&self);
tokio::spawn(async move { tokio::spawn(async move {
info!("Website crawler service started"); trace!("Website crawler service started");
let mut ticker = interval(service.check_interval); let mut ticker = interval(service.check_interval);
@ -59,7 +59,7 @@ impl WebsiteCrawlerService {
} }
async fn check_and_crawl_websites(&self) -> Result<(), Box<dyn std::error::Error + Send + Sync>> { async fn check_and_crawl_websites(&self) -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
info!("Checking for websites that need recrawling"); trace!("Checking for websites that need recrawling");
// First, scan for new USE WEBSITE commands in .bas files // First, scan for new USE WEBSITE commands in .bas files
self.scan_and_register_websites_from_scripts()?; self.scan_and_register_websites_from_scripts()?;
@ -75,9 +75,9 @@ impl WebsiteCrawlerService {
) )
.load(&mut conn)?; .load(&mut conn)?;
info!("Total websites in database: {}", all_websites.len()); trace!("Total websites in database: {}", all_websites.len());
for ws in &all_websites { for ws in &all_websites {
info!(" - URL: {}, status: {:?}, refresh: {:?}", ws.url, ws.crawl_status, ws.refresh_policy); trace!(" - URL: {}, status: {:?}, refresh: {:?}", ws.url, ws.crawl_status, ws.refresh_policy);
} }
let websites = diesel::sql_query( let websites = diesel::sql_query(
@ -90,7 +90,7 @@ impl WebsiteCrawlerService {
) )
.load::<WebsiteCrawlRecord>(&mut conn)?; .load::<WebsiteCrawlRecord>(&mut conn)?;
info!("Found {} websites to recrawl (next_crawl <= NOW())", websites.len()); trace!("Found {} websites to recrawl (next_crawl <= NOW())", websites.len());
// Process websites sequentially to prevent memory exhaustion // Process websites sequentially to prevent memory exhaustion
for website in websites { for website in websites {
@ -115,11 +115,11 @@ impl WebsiteCrawlerService {
let db_pool = self.db_pool.clone(); let db_pool = self.db_pool.clone();
let active_crawls = Arc::clone(&self.active_crawls); let active_crawls = Arc::clone(&self.active_crawls);
info!("Processing website: {}", website.url); trace!("Processing website: {}", website.url);
match Self::crawl_website(website, kb_manager, db_pool, active_crawls).await { match Self::crawl_website(website, kb_manager, db_pool, active_crawls).await {
Ok(_) => { Ok(_) => {
info!("Successfully processed website crawl"); trace!("Successfully processed website crawl");
} }
Err(e) => { Err(e) => {
error!("Failed to crawl website: {}", e); error!("Failed to crawl website: {}", e);
@ -165,7 +165,7 @@ impl WebsiteCrawlerService {
}); });
}; };
info!("Starting crawl for website: {}", website.url); trace!("Starting crawl for website: {}", website.url);
let config_manager = ConfigManager::new(db_pool.clone()); let config_manager = ConfigManager::new(db_pool.clone());
@ -200,7 +200,7 @@ impl WebsiteCrawlerService {
match crawler.crawl().await { match crawler.crawl().await {
Ok(pages) => { Ok(pages) => {
info!("Crawled {} pages from {}", pages.len(), website.url); trace!("Crawled {} pages from {}", pages.len(), website.url);
let mut conn = db_pool.get()?; let mut conn = db_pool.get()?;
#[derive(QueryableByName)] #[derive(QueryableByName)]
@ -228,7 +228,7 @@ impl WebsiteCrawlerService {
let total_pages = pages.len(); let total_pages = pages.len();
for (batch_idx, batch) in pages.chunks(BATCH_SIZE).enumerate() { for (batch_idx, batch) in pages.chunks(BATCH_SIZE).enumerate() {
info!("Processing batch {} of {} pages", batch_idx + 1, total_pages.div_ceil(BATCH_SIZE)); trace!("Processing batch {} of {} pages", batch_idx + 1, total_pages.div_ceil(BATCH_SIZE));
for (idx, page) in batch.iter().enumerate() { for (idx, page) in batch.iter().enumerate() {
let global_idx = batch_idx * BATCH_SIZE + idx; let global_idx = batch_idx * BATCH_SIZE + idx;
@ -258,7 +258,7 @@ impl WebsiteCrawlerService {
if batch_idx == 0 || (batch_idx + 1) % 2 == 0 { if batch_idx == 0 || (batch_idx + 1) % 2 == 0 {
// Index every 2 batches to prevent memory buildup // Index every 2 batches to prevent memory buildup
match kb_manager.index_kb_folder(&bot_name, &kb_name, &work_path).await { match kb_manager.index_kb_folder(&bot_name, &kb_name, &work_path).await {
Ok(_) => info!("Indexed batch {} successfully", batch_idx + 1), Ok(_) => trace!("Indexed batch {} successfully", batch_idx + 1),
Err(e) => warn!("Failed to index batch {}: {}", batch_idx + 1, e), Err(e) => warn!("Failed to index batch {}: {}", batch_idx + 1, e),
} }
@ -290,7 +290,7 @@ impl WebsiteCrawlerService {
.bind::<diesel::sql_types::Uuid, _>(&website.id) .bind::<diesel::sql_types::Uuid, _>(&website.id)
.execute(&mut conn)?; .execute(&mut conn)?;
info!( trace!(
"Successfully recrawled {}, next crawl: {:?}", "Successfully recrawled {}, next crawl: {:?}",
website.url, config.next_crawl website.url, config.next_crawl
); );
@ -318,7 +318,7 @@ impl WebsiteCrawlerService {
} }
fn scan_and_register_websites_from_scripts(&self) -> Result<(), Box<dyn std::error::Error + Send + Sync>> { fn scan_and_register_websites_from_scripts(&self) -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
info!("Scanning .bas files for USE WEBSITE commands"); trace!("Scanning .bas files for USE WEBSITE commands");
let work_dir = std::path::Path::new("work"); let work_dir = std::path::Path::new("work");
if !work_dir.exists() { if !work_dir.exists() {
@ -416,7 +416,7 @@ impl WebsiteCrawlerService {
.unwrap_or(0); .unwrap_or(0);
if exists == 0 { if exists == 0 {
info!("Auto-registering website {} for bot {} with refresh: {}", url_str, bot_id, refresh_str); trace!("Auto-registering website {} for bot {} with refresh: {}", url_str, bot_id, refresh_str);
// Register website for crawling with refresh policy // Register website for crawling with refresh policy
crate::basic::keywords::use_website::register_website_for_crawling_with_refresh( crate::basic::keywords::use_website::register_website_for_crawling_with_refresh(
@ -480,7 +480,7 @@ pub async fn ensure_crawler_service_running(
drop(service.start()); drop(service.start());
info!("Website crawler service initialized"); trace!("Website crawler service initialized");
Ok(()) Ok(())
} else { } else {

2
src/core/package_manager/installer.rs
View file

@ -1080,7 +1080,7 @@ EOF"#.to_string(),
component.name, component.name,
rendered_cmd rendered_cmd
); );
trace!("[START] Working dir: {}", bin_path.display()); trace!("Working dir: {}", bin_path.display());
let child = SafeCommand::new("sh") let child = SafeCommand::new("sh")
.and_then(|c| c.arg("-c")) .and_then(|c| c.arg("-c"))
.and_then(|c| c.trusted_shell_script_arg(&rendered_cmd)) .and_then(|c| c.trusted_shell_script_arg(&rendered_cmd))

12
src/core/shared/memory_monitor.rs
View file

@ -31,7 +31,7 @@ component: component.to_string(),
if let Ok(mut registry) = THREAD_REGISTRY.write() { if let Ok(mut registry) = THREAD_REGISTRY.write() {
registry.insert(name.to_string(), info); registry.insert(name.to_string(), info);
} }
trace!("[THREAD] Registered: {} (component: {})", name, component); trace!("Registered: {} (component: {})", name, component);
} }
pub fn record_thread_activity(name: &str) { pub fn record_thread_activity(name: &str) {
@ -47,12 +47,12 @@ pub fn unregister_thread(name: &str) {
if let Ok(mut registry) = THREAD_REGISTRY.write() { if let Ok(mut registry) = THREAD_REGISTRY.write() {
registry.remove(name); registry.remove(name);
} }
info!("[THREAD] Unregistered: {}", name); info!("Unregistered: {}", name);
} }
pub fn log_thread_stats() { pub fn log_thread_stats() {
if let Ok(registry) = THREAD_REGISTRY.read() { if let Ok(registry) = THREAD_REGISTRY.read() {
info!("[THREADS] Active thread count: {}", registry.len()); info!("Active thread count: {}", registry.len());
for (name, info) in registry.iter() { for (name, info) in registry.iter() {
let uptime = info.started_at.elapsed().as_secs(); let uptime = info.started_at.elapsed().as_secs();
let idle = info.last_activity.elapsed().as_secs(); let idle = info.last_activity.elapsed().as_secs();
@ -185,7 +185,7 @@ if let Some(stats) = get_jemalloc_stats() {
stats.log(); stats.log();
let frag = stats.fragmentation_ratio(); let frag = stats.fragmentation_ratio();
if frag > 1.5 { if frag > 1.5 {
warn!("[JEMALLOC] High fragmentation detected: {:.2}x", frag); warn!("High fragmentation detected: {:.2}x", frag);
} }
} }
} }
@ -446,7 +446,7 @@ tokio::spawn(async move {
record_component("global"); record_component("global");
if let Some(warning) = detector.check() { if let Some(warning) = detector.check() {
warn!("[MONITOR] {}", warning); warn!("{}", warning);
stats.log(); stats.log();
log_component_stats(); log_component_stats();
log_thread_stats(); log_thread_stats();
@ -454,7 +454,7 @@ tokio::spawn(async move {
// Switch to normal interval after startup period // Switch to normal interval after startup period
if tick_count == startup_ticks { if tick_count == startup_ticks {
trace!("[MONITOR] Switching to normal interval ({}s)", interval_secs); trace!("Switching to normal interval ({}s)", interval_secs);
interval = tokio::time::interval(normal_interval); interval = tokio::time::interval(normal_interval);
} }
} }

10
src/core/shared/state.rs
View file

@ -505,7 +505,7 @@ impl std::fmt::Debug for AppState {
impl AppState { impl AppState {
pub fn broadcast_task_progress(&self, event: TaskProgressEvent) { pub fn broadcast_task_progress(&self, event: TaskProgressEvent) {
log::info!( log::info!(
"[TASK_PROGRESS] Broadcasting: task_id={}, step={}, message={}", "Broadcasting: task_id={}, step={}, message={}",
event.task_id, event.task_id,
event.step, event.step,
event.message event.message
@ -513,19 +513,19 @@ impl AppState {
if let Some(tx) = &self.task_progress_broadcast { if let Some(tx) = &self.task_progress_broadcast {
let receiver_count = tx.receiver_count(); let receiver_count = tx.receiver_count();
log::info!( log::info!(
"[TASK_PROGRESS] Broadcast channel has {} receivers", "Broadcast channel has {} receivers",
receiver_count receiver_count
); );
match tx.send(event) { match tx.send(event) {
Ok(_) => { Ok(_) => {
log::info!("[TASK_PROGRESS] Event sent successfully"); log::info!("Event sent successfully");
} }
Err(e) => { Err(e) => {
log::warn!("[TASK_PROGRESS] No listeners for task progress: {e}"); log::warn!("No listeners for task progress: {e}");
} }
} }
} else { } else {
log::warn!("[TASK_PROGRESS] No broadcast channel configured!"); log::warn!("No broadcast channel configured!");
} }
} }

44
src/drive/drive_monitor/mod.rs
View file

@ -211,7 +211,7 @@ impl DriveMonitor {
// Check if already processing to prevent duplicate monitoring // Check if already processing to prevent duplicate monitoring
if self.is_processing.load(std::sync::atomic::Ordering::Acquire) { if self.is_processing.load(std::sync::atomic::Ordering::Acquire) {
warn!("[DRIVE_MONITOR] Already processing for bot {}, skipping", self.bot_id); warn!("Already processing for bot {}, skipping", self.bot_id);
return Ok(()); return Ok(());
} }
@ -234,18 +234,18 @@ impl DriveMonitor {
.store(true, std::sync::atomic::Ordering::SeqCst); .store(true, std::sync::atomic::Ordering::SeqCst);
trace!("start_monitoring: calling check_for_changes..."); trace!("start_monitoring: calling check_for_changes...");
info!("[DRIVE_MONITOR] Calling initial check_for_changes..."); info!("Calling initial check_for_changes...");
match tokio::time::timeout(Duration::from_secs(300), self.check_for_changes()).await { match tokio::time::timeout(Duration::from_secs(300), self.check_for_changes()).await {
Ok(Ok(_)) => { Ok(Ok(_)) => {
self.consecutive_failures.store(0, Ordering::Relaxed); self.consecutive_failures.store(0, Ordering::Relaxed);
} }
Ok(Err(e)) => { Ok(Err(e)) => {
warn!("[DRIVE_MONITOR] Initial check failed (will retry): {}", e); warn!("Initial check failed (will retry): {}", e);
self.consecutive_failures.fetch_add(1, Ordering::Relaxed); self.consecutive_failures.fetch_add(1, Ordering::Relaxed);
} }
Err(_) => { Err(_) => {
error!("[DRIVE_MONITOR] Initial check timed out after 5 minutes"); error!("Initial check timed out after 5 minutes");
self.consecutive_failures.fetch_add(1, Ordering::Relaxed); self.consecutive_failures.fetch_add(1, Ordering::Relaxed);
} }
} }
@ -260,15 +260,15 @@ impl DriveMonitor {
// Force enable periodic monitoring regardless of initial check result // Force enable periodic monitoring regardless of initial check result
self.is_processing.store(true, std::sync::atomic::Ordering::SeqCst); self.is_processing.store(true, std::sync::atomic::Ordering::SeqCst);
info!("[DRIVE_MONITOR] Forced is_processing to true for periodic monitoring"); info!("Forced is_processing to true for periodic monitoring");
let self_clone = self.clone(); // Don't wrap in Arc::new - that creates a copy let self_clone = self.clone(); // Don't wrap in Arc::new - that creates a copy
tokio::spawn(async move { tokio::spawn(async move {
let mut consecutive_processing_failures = 0; let mut consecutive_processing_failures = 0;
info!("[DRIVE_MONITOR] Starting periodic monitoring loop for bot {}", self_clone.bot_id); info!("Starting periodic monitoring loop for bot {}", self_clone.bot_id);
let is_processing_state = self_clone.is_processing.load(std::sync::atomic::Ordering::SeqCst); let is_processing_state = self_clone.is_processing.load(std::sync::atomic::Ordering::SeqCst);
info!("[DRIVE_MONITOR] is_processing state at loop start: {} for bot {}", is_processing_state, self_clone.bot_id); info!("is_processing state at loop start: {} for bot {}", is_processing_state, self_clone.bot_id);
while self_clone while self_clone
.is_processing .is_processing
@ -288,7 +288,7 @@ impl DriveMonitor {
.fetch_add(1, Ordering::Relaxed) .fetch_add(1, Ordering::Relaxed)
+ 1; + 1;
if failures % 10 == 1 { if failures % 10 == 1 {
warn!("[DRIVE_MONITOR] S3/MinIO unavailable for bucket {} (failures: {}), backing off to {:?}", warn!("S3/MinIO unavailable for bucket {} (failures: {}), backing off to {:?}",
self_clone.bucket_name, failures, self_clone.calculate_backoff()); self_clone.bucket_name, failures, self_clone.calculate_backoff());
} }
continue; continue;
@ -302,7 +302,7 @@ impl DriveMonitor {
self_clone.consecutive_failures.swap(0, Ordering::Relaxed); self_clone.consecutive_failures.swap(0, Ordering::Relaxed);
consecutive_processing_failures = 0; consecutive_processing_failures = 0;
if prev_failures > 0 { if prev_failures > 0 {
info!("[DRIVE_MONITOR] S3/MinIO recovered for bucket {} after {} failures", info!("S3/MinIO recovered for bucket {} after {} failures",
self_clone.bucket_name, prev_failures); self_clone.bucket_name, prev_failures);
} }
} }
@ -315,18 +315,18 @@ impl DriveMonitor {
// If too many consecutive failures, stop processing temporarily // If too many consecutive failures, stop processing temporarily
if consecutive_processing_failures > 10 { if consecutive_processing_failures > 10 {
error!("[DRIVE_MONITOR] Too many consecutive failures ({}), stopping processing for bot {}", error!("Too many consecutive failures ({}), stopping processing for bot {}",
consecutive_processing_failures, self_clone.bot_id); consecutive_processing_failures, self_clone.bot_id);
self_clone.is_processing.store(false, std::sync::atomic::Ordering::SeqCst); self_clone.is_processing.store(false, std::sync::atomic::Ordering::SeqCst);
break; break;
} }
} }
Err(_) => { Err(_) => {
error!("[DRIVE_MONITOR] check_for_changes timed out for bot {}", self_clone.bot_id); error!("check_for_changes timed out for bot {}", self_clone.bot_id);
consecutive_processing_failures += 1; consecutive_processing_failures += 1;
if consecutive_processing_failures > 5 { if consecutive_processing_failures > 5 {
error!("[DRIVE_MONITOR] Too many timeouts, stopping processing for bot {}", self_clone.bot_id); error!("Too many timeouts, stopping processing for bot {}", self_clone.bot_id);
self_clone.is_processing.store(false, std::sync::atomic::Ordering::SeqCst); self_clone.is_processing.store(false, std::sync::atomic::Ordering::SeqCst);
break; break;
} }
@ -334,7 +334,7 @@ impl DriveMonitor {
} }
} }
info!("[DRIVE_MONITOR] Monitoring loop ended for bot {}", self_clone.bot_id); info!("Monitoring loop ended for bot {}", self_clone.bot_id);
}); });
info!("DriveMonitor started for bot {}", self.bot_id); info!("DriveMonitor started for bot {}", self.bot_id);
@ -373,7 +373,7 @@ impl DriveMonitor {
if !self.check_drive_health().await { if !self.check_drive_health().await {
let failures = self.consecutive_failures.fetch_add(1, Ordering::Relaxed) + 1; let failures = self.consecutive_failures.fetch_add(1, Ordering::Relaxed) + 1;
if failures % 10 == 1 { if failures % 10 == 1 {
warn!("[DRIVE_MONITOR] S3/MinIO unavailable for bucket {} (failures: {}), backing off to {:?}", warn!("S3/MinIO unavailable for bucket {} (failures: {}), backing off to {:?}",
self.bucket_name, failures, self.calculate_backoff()); self.bucket_name, failures, self.calculate_backoff());
} }
continue; continue;
@ -385,7 +385,7 @@ impl DriveMonitor {
Ok(_) => { Ok(_) => {
let prev_failures = self.consecutive_failures.swap(0, Ordering::Relaxed); let prev_failures = self.consecutive_failures.swap(0, Ordering::Relaxed);
if prev_failures > 0 { if prev_failures > 0 {
info!("[DRIVE_MONITOR] S3/MinIO recovered for bucket {} after {} failures", info!("S3/MinIO recovered for bucket {} after {} failures",
self.bucket_name, prev_failures); self.bucket_name, prev_failures);
} }
} }
@ -408,12 +408,12 @@ impl DriveMonitor {
); );
let Some(client) = &self.state.drive else { let Some(client) = &self.state.drive else {
warn!("[DRIVE_MONITOR] No drive client available for bot {}, skipping file monitoring", self.bot_id); warn!("No drive client available for bot {}, skipping file monitoring", self.bot_id);
return Ok(()); return Ok(());
}; };
trace!("check_for_changes: calling check_gbdialog_changes..."); trace!("check_for_changes: calling check_gbdialog_changes...");
trace!("[DRIVE_MONITOR] Checking gbdialog..."); trace!("Checking gbdialog...");
self.check_gbdialog_changes(client).await?; self.check_gbdialog_changes(client).await?;
trace!("check_for_changes: check_gbdialog_changes done"); trace!("check_for_changes: check_gbdialog_changes done");
let after_dialog = MemoryStats::current(); let after_dialog = MemoryStats::current();
@ -424,7 +424,7 @@ impl DriveMonitor {
); );
trace!("check_for_changes: calling check_gbot..."); trace!("check_for_changes: calling check_gbot...");
trace!("[DRIVE_MONITOR] Checking gbot..."); trace!("Checking gbot...");
self.check_gbot(client).await?; self.check_gbot(client).await?;
trace!("check_for_changes: check_gbot done"); trace!("check_for_changes: check_gbot done");
let after_gbot = MemoryStats::current(); let after_gbot = MemoryStats::current();
@ -435,7 +435,7 @@ impl DriveMonitor {
); );
trace!("check_for_changes: calling check_gbkb_changes..."); trace!("check_for_changes: calling check_gbkb_changes...");
trace!("[DRIVE_MONITOR] Checking gbkb..."); trace!("Checking gbkb...");
self.check_gbkb_changes(client).await?; self.check_gbkb_changes(client).await?;
trace!("check_for_changes: check_gbkb_changes done"); trace!("check_for_changes: check_gbkb_changes done");
let after_gbkb = MemoryStats::current(); let after_gbkb = MemoryStats::current();
@ -531,7 +531,7 @@ impl DriveMonitor {
let self_clone = Arc::new(self.clone()); let self_clone = Arc::new(self.clone());
tokio::spawn(async move { tokio::spawn(async move {
if let Err(e) = self_clone.save_file_states().await { if let Err(e) = self_clone.save_file_states().await {
warn!("[DRIVE_MONITOR] Failed to save file states: {}", e); warn!("Failed to save file states: {}", e);
} }
}); });
Ok(()) Ok(())
@ -1145,7 +1145,7 @@ impl DriveMonitor {
#[cfg(any(feature = "research", feature = "llm"))] #[cfg(any(feature = "research", feature = "llm"))]
{ {
if !is_embedding_server_ready() { if !is_embedding_server_ready() {
info!("[DRIVE_MONITOR] Embedding server not ready, deferring KB indexing for {}", kb_folder_path.display()); info!("Embedding server not ready, deferring KB indexing for {}", kb_folder_path.display());
continue; continue;
} }
@ -1256,7 +1256,7 @@ impl DriveMonitor {
let self_clone = Arc::new(self.clone()); let self_clone = Arc::new(self.clone());
tokio::spawn(async move { tokio::spawn(async move {
if let Err(e) = self_clone.save_file_states().await { if let Err(e) = self_clone.save_file_states().await {
warn!("[DRIVE_MONITOR] Failed to save file states: {}", e); warn!("Failed to save file states: {}", e);
} }
}); });

38
src/drive/local_file_monitor.rs
View file

@ -36,7 +36,7 @@ impl LocalFileMonitor {
// Use botserver/work as the work directory for generated files // Use botserver/work as the work directory for generated files
let work_root = PathBuf::from("work"); let work_root = PathBuf::from("work");
info!("[LOCAL_MONITOR] Initializing with data_dir: {:?}, work_root: {:?}", data_dir, work_root); info!("Initializing with data_dir: {:?}, work_root: {:?}", data_dir, work_root);
Self { Self {
state, state,
@ -48,11 +48,11 @@ impl LocalFileMonitor {
} }
pub async fn start_monitoring(&self) -> Result<(), Box<dyn Error + Send + Sync>> { pub async fn start_monitoring(&self) -> Result<(), Box<dyn Error + Send + Sync>> {
info!("[LOCAL_MONITOR] Starting local file monitor for /opt/gbo/data/*.gbai directories"); info!("Starting local file monitor for /opt/gbo/data/*.gbai directories");
// Create data directory if it doesn't exist // Create data directory if it doesn't exist
if let Err(e) = tokio::fs::create_dir_all(&self.data_dir).await { if let Err(e) = tokio::fs::create_dir_all(&self.data_dir).await {
warn!("[LOCAL_MONITOR] Failed to create data directory: {}", e); warn!("Failed to create data directory: {}", e);
} }
// Initial scan of all .gbai directories // Initial scan of all .gbai directories
@ -66,12 +66,12 @@ impl LocalFileMonitor {
monitor.monitoring_loop().await; monitor.monitoring_loop().await;
}); });
info!("[LOCAL_MONITOR] Local file monitor started"); info!("Local file monitor started");
Ok(()) Ok(())
} }
async fn monitoring_loop(&self) { async fn monitoring_loop(&self) {
info!("[LOCAL_MONITOR] Starting monitoring loop"); info!("Starting monitoring loop");
// Try to create a file system watcher // Try to create a file system watcher
let (tx, mut rx) = tokio::sync::mpsc::channel(100); let (tx, mut rx) = tokio::sync::mpsc::channel(100);
@ -88,7 +88,7 @@ impl LocalFileMonitor {
) { ) {
Ok(w) => w, Ok(w) => w,
Err(e) => { Err(e) => {
error!("[LOCAL_MONITOR] Failed to create watcher: {}. Falling back to polling.", e); error!("Failed to create watcher: {}. Falling back to polling.", e);
// Fall back to polling if watcher creation fails // Fall back to polling if watcher creation fails
self.polling_loop().await; self.polling_loop().await;
return; return;
@ -97,13 +97,13 @@ impl LocalFileMonitor {
// Watch the data directory // Watch the data directory
if let Err(e) = watcher.watch(&self.data_dir, RecursiveMode::Recursive) { if let Err(e) = watcher.watch(&self.data_dir, RecursiveMode::Recursive) {
warn!("[LOCAL_MONITOR] Failed to watch directory {:?}: {}. Using polling fallback.", self.data_dir, e); warn!("Failed to watch directory {:?}: {}. Using polling fallback.", self.data_dir, e);
drop(watcher); drop(watcher);
self.polling_loop().await; self.polling_loop().await;
return; return;
} }
info!("[LOCAL_MONITOR] Watching directory: {:?}", self.data_dir); info!("Watching directory: {:?}", self.data_dir);
while self.is_processing.load(Ordering::SeqCst) { while self.is_processing.load(Ordering::SeqCst) {
tokio::time::sleep(Duration::from_secs(5)).await; tokio::time::sleep(Duration::from_secs(5)).await;
@ -114,9 +114,9 @@ impl LocalFileMonitor {
EventKind::Create(_) | EventKind::Modify(_) | EventKind::Any => { EventKind::Create(_) | EventKind::Modify(_) | EventKind::Any => {
for path in &event.paths { for path in &event.paths {
if self.is_gbdialog_file(path) { if self.is_gbdialog_file(path) {
info!("[LOCAL_MONITOR] Detected change: {:?}", path); info!("Detected change: {:?}", path);
if let Err(e) = self.compile_local_file(path).await { if let Err(e) = self.compile_local_file(path).await {
error!("[LOCAL_MONITOR] Failed to compile {:?}: {}", path, e); error!("Failed to compile {:?}: {}", path, e);
} }
} }
} }
@ -124,7 +124,7 @@ impl LocalFileMonitor {
EventKind::Remove(_) => { EventKind::Remove(_) => {
for path in &event.paths { for path in &event.paths {
if self.is_gbdialog_file(path) { if self.is_gbdialog_file(path) {
info!("[LOCAL_MONITOR] File removed: {:?}", path); info!("File removed: {:?}", path);
self.remove_file_state(path).await; self.remove_file_state(path).await;
} }
} }
@ -135,21 +135,21 @@ impl LocalFileMonitor {
// Periodic scan to catch any missed changes // Periodic scan to catch any missed changes
if let Err(e) = self.scan_and_compile_all().await { if let Err(e) = self.scan_and_compile_all().await {
error!("[LOCAL_MONITOR] Scan failed: {}", e); error!("Scan failed: {}", e);
} }
} }
info!("[LOCAL_MONITOR] Monitoring loop ended"); info!("Monitoring loop ended");
} }
async fn polling_loop(&self) { async fn polling_loop(&self) {
info!("[LOCAL_MONITOR] Using polling fallback (checking every 10s)"); info!("Using polling fallback (checking every 10s)");
while self.is_processing.load(Ordering::SeqCst) { while self.is_processing.load(Ordering::SeqCst) {
tokio::time::sleep(Duration::from_secs(10)).await; tokio::time::sleep(Duration::from_secs(10)).await;
if let Err(e) = self.scan_and_compile_all().await { if let Err(e) = self.scan_and_compile_all().await {
error!("[LOCAL_MONITOR] Scan failed: {}", e); error!("Scan failed: {}", e);
} }
} }
} }
@ -229,9 +229,9 @@ impl LocalFileMonitor {
}; };
if should_compile { if should_compile {
info!("[LOCAL_MONITOR] Compiling: {:?}", path); info!("Compiling: {:?}", path);
if let Err(e) = self.compile_local_file(&path).await { if let Err(e) = self.compile_local_file(&path).await {
error!("[LOCAL_MONITOR] Failed to compile {:?}: {}", path, e); error!("Failed to compile {:?}: {}", path, e);
} }
// Update state // Update state
@ -304,7 +304,7 @@ impl LocalFileMonitor {
}) })
.await??; .await??;
info!("[LOCAL_MONITOR] Successfully compiled: {:?}", file_path); info!("Successfully compiled: {:?}", file_path);
Ok(()) Ok(())
} }
@ -315,7 +315,7 @@ impl LocalFileMonitor {
} }
pub async fn stop_monitoring(&self) { pub async fn stop_monitoring(&self) {
info!("[LOCAL_MONITOR] Stopping local file monitor"); info!("Stopping local file monitor");
self.is_processing.store(false, Ordering::SeqCst); self.is_processing.store(false, Ordering::SeqCst);
self.file_states.write().await.clear(); self.file_states.write().await.clear();
} }

2
src/llm/claude.rs
View file

@ -421,7 +421,7 @@ impl ClaudeClient {
if !status.is_success() { if !status.is_success() {
let error_text = response.text().await.unwrap_or_default(); let error_text = response.text().await.unwrap_or_default();
error!("[CLAUDE] Error response: {}", error_text); error!("Claude API error response: {}", error_text);
return Err(format!("HTTP {}: {}", status, error_text).into()); return Err(format!("HTTP {}: {}", status, error_text).into());
} }

4
src/llm/glm.rs
View file

@ -304,7 +304,7 @@ impl LLMProvider for GLMClient {
match tx.send(tool_call_json).await { match tx.send(tool_call_json).await {
Ok(_) => {}, Ok(_) => {},
Err(e) => { Err(e) => {
error!("[GLM_TX] Failed to send tool_call to channel: {}", e); error!("Failed to send tool_call to channel: {}", e);
} }
} }
} }
@ -318,7 +318,7 @@ impl LLMProvider for GLMClient {
match tx.send(content.to_string()).await { match tx.send(content.to_string()).await {
Ok(_) => {}, Ok(_) => {},
Err(e) => { Err(e) => {
error!("[GLM_TX] Failed to send to channel: {}", e); error!("Failed to send to channel: {}", e);
} }
} }
} }

13
src/llm/mod.rs
View file

@ -407,6 +407,19 @@ impl LLMProvider for OpenAIClient {
let _ = tx.send(processed).await; let _ = tx.send(processed).await;
} }
} }
// Handle standard OpenAI tool_calls
if let Some(tool_calls) = data["choices"][0]["delta"]["tool_calls"].as_array() {
for tool_call in tool_calls {
// We send the tool_call object as a JSON string so stream_response
// can buffer it and parse it using ToolExecutor::parse_tool_call
if let Some(func) = tool_call.get("function") {
if let Some(args) = func.get("arguments").and_then(|a| a.as_str()) {
let _ = tx.send(args.to_string()).await;
}
}
}
}
} }
} }
} }

26
src/tasks/task_api/handlers.rs
View file

@ -69,7 +69,7 @@ pub async fn handle_task_list(
let result = tokio::task::spawn_blocking(move || { let result = tokio::task::spawn_blocking(move || {
let mut db_conn = conn.get().map_err(|e| { let mut db_conn = conn.get().map_err(|e| {
error!("[TASK_LIST] DB connection error: {}", e); error!("DB connection error: {}", e);
diesel::result::Error::DatabaseError( diesel::result::Error::DatabaseError(
diesel::result::DatabaseErrorKind::UnableToSendCommand, diesel::result::DatabaseErrorKind::UnableToSendCommand,
Box::new(e.to_string()), Box::new(e.to_string()),
@ -95,7 +95,7 @@ pub async fn handle_task_list(
) )
.load::<AutoTaskRow>(&mut db_conn) .load::<AutoTaskRow>(&mut db_conn)
.map_err(|e| { .map_err(|e| {
error!("[TASK_LIST] Query error: {}", e); error!("Query error: {}", e);
e e
})?; })?;
@ -106,11 +106,11 @@ pub async fn handle_task_list(
match result { match result {
Ok(Ok(tasks)) => (StatusCode::OK, axum::Json(tasks)).into_response(), Ok(Ok(tasks)) => (StatusCode::OK, axum::Json(tasks)).into_response(),
Ok(Err(e)) => { Ok(Err(e)) => {
error!("[TASK_LIST] DB error: {}", e); error!("DB error: {}", e);
(StatusCode::INTERNAL_SERVER_ERROR, "Database error").into_response() (StatusCode::INTERNAL_SERVER_ERROR, "Database error").into_response()
} }
Err(e) => { Err(e) => {
error!("[TASK_LIST] Task join error: {}", e); error!("Task join error: {}", e);
(StatusCode::INTERNAL_SERVER_ERROR, "Internal server error").into_response() (StatusCode::INTERNAL_SERVER_ERROR, "Internal server error").into_response()
} }
} }
@ -122,7 +122,7 @@ pub async fn handle_task_get(
Path(id): Path<String>, Path(id): Path<String>,
headers: axum::http::HeaderMap, headers: axum::http::HeaderMap,
) -> impl IntoResponse { ) -> impl IntoResponse {
info!("[TASK_GET] *** Handler called for task: {} ***", id); info!("*** Handler called for task: {} ***", id);
// Check if client wants JSON (for polling) vs HTML (for HTMX) // Check if client wants JSON (for polling) vs HTML (for HTMX)
let wants_json = headers let wants_json = headers
@ -138,7 +138,7 @@ pub async fn handle_task_get(
let mut db_conn = conn let mut db_conn = conn
.get() .get()
.map_err(|e| { .map_err(|e| {
error!("[TASK_GET] DB connection error: {}", e); error!("DB connection error: {}", e);
format!("DB connection error: {}", e) format!("DB connection error: {}", e)
})?; })?;
@ -176,11 +176,11 @@ pub async fn handle_task_get(
let parsed_uuid = match Uuid::parse_str(&task_id) { let parsed_uuid = match Uuid::parse_str(&task_id) {
Ok(u) => { Ok(u) => {
info!("[TASK_GET] Parsed UUID: {}", u); info!("Parsed UUID: {}", u);
u u
} }
Err(e) => { Err(e) => {
error!("[TASK_GET] Invalid task ID '{}': {}", task_id, e); error!("Invalid task ID '{}': {}", task_id, e);
return Err(format!("Invalid task ID: {}", task_id)); return Err(format!("Invalid task ID: {}", task_id));
} }
}; };
@ -192,12 +192,12 @@ pub async fn handle_task_get(
.bind::<diesel::sql_types::Uuid, _>(parsed_uuid) .bind::<diesel::sql_types::Uuid, _>(parsed_uuid)
.get_result(&mut db_conn) .get_result(&mut db_conn)
.map_err(|e| { .map_err(|e| {
error!("[TASK_GET] Query error for {}: {}", parsed_uuid, e); error!("Query error for {}: {}", parsed_uuid, e);
e e
}) })
.ok(); .ok();
info!("[TASK_GET] Query result for {}: found={}", parsed_uuid, task.is_some()); info!("Query result for {}: found={}", parsed_uuid, task.is_some());
Ok::<_, String>(task) Ok::<_, String>(task)
}) })
.await .await
@ -208,7 +208,7 @@ pub async fn handle_task_get(
match result { match result {
Ok(Some(task)) => { Ok(Some(task)) => {
info!("[TASK_GET] Returning task: {} - {} (wants_json={})", task.id, task.title, wants_json); info!("Returning task: {} - {} (wants_json={})", task.id, task.title, wants_json);
// Return JSON for API polling clients // Return JSON for API polling clients
if wants_json { if wants_json {
@ -371,11 +371,11 @@ pub async fn handle_task_get(
(StatusCode::OK, axum::response::Html(html)).into_response() (StatusCode::OK, axum::response::Html(html)).into_response()
} }
Ok(None) => { Ok(None) => {
warn!("[TASK_GET] Task not found: {}", id); warn!("Task not found: {}", id);
(StatusCode::NOT_FOUND, axum::response::Html("<div class='error'>Task not found</div>".to_string())).into_response() (StatusCode::NOT_FOUND, axum::response::Html("<div class='error'>Task not found</div>".to_string())).into_response()
} }
Err(e) => { Err(e) => {
error!("[TASK_GET] Error fetching task {}: {}", id, e); error!("Error fetching task {}: {}", id, e);
(StatusCode::INTERNAL_SERVER_ERROR, axum::response::Html(format!("<div class='error'>{}</div>", e))).into_response() (StatusCode::INTERNAL_SERVER_ERROR, axum::response::Html(format!("<div class='error'>{}</div>", e))).into_response()
} }
} }

20
src/tasks/task_api/html_renderers.rs
View file

@ -62,12 +62,12 @@ pub fn build_terminal_html(step_results: &Option<serde_json::Value>, status: &st
} }
pub fn build_taskmd_html(state: &Arc<AppState>, task_id: &str, title: &str, runtime: &str, db_manifest: Option<&serde_json::Value>) -> (String, String) { pub fn build_taskmd_html(state: &Arc<AppState>, task_id: &str, title: &str, runtime: &str, db_manifest: Option<&serde_json::Value>) -> (String, String) {
log::info!("[TASKMD_HTML] Building TASK.md view for task_id: {}", task_id); log::info!("Building TASK.md view for task_id: {}", task_id);
// First, try to get manifest from in-memory cache (for active/running tasks) // First, try to get manifest from in-memory cache (for active/running tasks)
if let Ok(manifests) = state.task_manifests.read() { if let Ok(manifests) = state.task_manifests.read() {
if let Some(manifest) = manifests.get(task_id) { if let Some(manifest) = manifests.get(task_id) {
log::info!("[TASKMD_HTML] Found manifest in memory for task: {} with {} sections", manifest.app_name, manifest.sections.len()); log::info!("Found manifest in memory for task: {} with {} sections", manifest.app_name, manifest.sections.len());
let status_html = build_status_section_html(manifest, title, runtime); let status_html = build_status_section_html(manifest, title, runtime);
let progress_html = build_progress_log_html(manifest); let progress_html = build_progress_log_html(manifest);
return (status_html, progress_html); return (status_html, progress_html);
@ -76,25 +76,25 @@ pub fn build_taskmd_html(state: &Arc<AppState>, task_id: &str, title: &str, runt
// If not in memory, try to load from database (for completed/historical tasks) // If not in memory, try to load from database (for completed/historical tasks)
if let Some(manifest_json) = db_manifest { if let Some(manifest_json) = db_manifest {
log::info!("[TASKMD_HTML] Found manifest in database for task: {}", task_id); log::info!("Found manifest in database for task: {}", task_id);
if let Ok(manifest) = serde_json::from_value::<TaskManifest>(manifest_json.clone()) { if let Ok(manifest) = serde_json::from_value::<TaskManifest>(manifest_json.clone()) {
log::info!("[TASKMD_HTML] Parsed DB manifest for task: {} with {} sections", manifest.app_name, manifest.sections.len()); log::info!("Parsed DB manifest for task: {} with {} sections", manifest.app_name, manifest.sections.len());
let status_html = build_status_section_html(&manifest, title, runtime); let status_html = build_status_section_html(&manifest, title, runtime);
let progress_html = build_progress_log_html(&manifest); let progress_html = build_progress_log_html(&manifest);
return (status_html, progress_html); return (status_html, progress_html);
} else { } else {
// Try parsing as web JSON format (the format we store) // Try parsing as web JSON format (the format we store)
if let Some(web_manifest) = super::utils::parse_web_manifest_json(manifest_json) { if let Some(web_manifest) = super::utils::parse_web_manifest_json(manifest_json) {
log::info!("[TASKMD_HTML] Parsed web manifest from DB for task: {}", task_id); log::info!("Parsed web manifest from DB for task: {}", task_id);
let status_html = build_status_section_from_web_json(&web_manifest, title, runtime); let status_html = build_status_section_from_web_json(&web_manifest, title, runtime);
let progress_html = build_progress_log_from_web_json(&web_manifest); let progress_html = build_progress_log_from_web_json(&web_manifest);
return (status_html, progress_html); return (status_html, progress_html);
} }
log::warn!("[TASKMD_HTML] Failed to parse manifest JSON for task: {}", task_id); log::warn!("Failed to parse manifest JSON for task: {}", task_id);
} }
} }
log::info!("[TASKMD_HTML] No manifest found for task: {}", task_id); log::info!("No manifest found for task: {}", task_id);
let default_status = format!(r#" let default_status = format!(r#"
<div class="status-row"> <div class="status-row">
@ -326,10 +326,10 @@ fn build_progress_log_html(manifest: &TaskManifest) -> String {
let total_steps = manifest.total_steps; let total_steps = manifest.total_steps;
log::info!("[PROGRESS_HTML] Building progress log, {} sections, total_steps={}", manifest.sections.len(), total_steps); log::info!("Building progress log, {} sections, total_steps={}", manifest.sections.len(), total_steps);
for section in &manifest.sections { for section in &manifest.sections {
log::info!("[PROGRESS_HTML] Section '{}': children={}, items={}, item_groups={}", log::info!("Section '{}': children={}, items={}, item_groups={}",
section.name, section.children.len(), section.items.len(), section.item_groups.len()); section.name, section.children.len(), section.items.len(), section.item_groups.len());
let section_class = match section.status { let section_class = match section.status {
crate::auto_task::SectionStatus::Completed => "completed expanded", crate::auto_task::SectionStatus::Completed => "completed expanded",
@ -362,7 +362,7 @@ fn build_progress_log_html(manifest: &TaskManifest) -> String {
"#, section_class, section.id, section.name, global_current, total_steps, section_class, status_text, section_class)); "#, section_class, section.id, section.name, global_current, total_steps, section_class, status_text, section_class));
for child in &section.children { for child in &section.children {
log::info!("[PROGRESS_HTML] Child '{}': items={}, item_groups={}", log::info!(" Child '{}': items={}, item_groups={}",
child.name, child.items.len(), child.item_groups.len()); child.name, child.items.len(), child.item_groups.len());
let child_class = match child.status { let child_class = match child.status {
crate::auto_task::SectionStatus::Completed => "completed expanded", crate::auto_task::SectionStatus::Completed => "completed expanded",