Add a bunch of logging to ai.rs

src/commands/ai.rs

@@ -1,5 +1,6 @@
 use crate::{Context, Error};
-use tracing::{debug, error, trace};
+use crate::messaging::trace_message;
+use tracing::{debug, error, info, trace, warn};
 use ollama_rs::Ollama;
 use std::env;
 use std::time::Duration;
@@ -18,66 +19,119 @@ pub async fn prompt(
     #[description = "Include recent messages (max 10)"]
     include_messages: Option<u8>,
 ) -> Result<(), Error> {
-    debug!("{} has requested to prompt EwiAI with '{}'", ctx.author().name, prompt);
+    let channel_str = ctx.channel_id().to_string();
+    let guild_str = ctx.guild_id().map_or_else(|| "DM".to_string(), |g| g.to_string());
 
+    trace!("prompt command called by user {} (ID: {}) in channel {} (guild: {})", ctx.author().name, ctx.author().id, channel_str, guild_str);
+    debug!("{} has requested to prompt EwiAI with '{}' (include_messages: {:?})", ctx.author().name, prompt, include_messages);
+
+    trace!("Checking environment variable TG_BOT_OLLAMA_HOST...");
     let host = match env::var("TG_BOT_OLLAMA_HOST") {
-        Ok(h) => h,
+        Ok(h) => {
-        Err(_) => {
+            trace!("Successfully retrieved TG_BOT_OLLAMA_HOST = {}", h);
-            ctx.say("Error: Expected an ollama url in the environment (`TG_BOT_OLLAMA_HOST`).").await?;
+            h
+        }
+        Err(e) => {
+            warn!("TG_BOT_OLLAMA_HOST environment variable missing: {}", e);
+            let err_msg = "Error: Expected an ollama url in the environment (`TG_BOT_OLLAMA_HOST`).";
+            trace_message(err_msg.to_string(), channel_str.clone(), guild_str.clone()).await;
+            ctx.say(err_msg).await?;
             return Ok(());
         }
     };
 
     let formatted_host = if !host.starts_with("http://") && !host.starts_with("https://") {
-        format!("http://{}", host)
+        let f = format!("http://{}", host);
+        trace!("Formatted Ollama host address to include http:// prefix: {}", f);
+        f
     } else {
+        trace!("Ollama host address already has URL scheme: {}", host);
         host
     };
 
+    trace!("Building Ollama client instance for host {} on port 11434...", formatted_host);
     let ollama = Ollama::builder()
         .host(&formatted_host)
         .port(11434)
         .build();
 
+    trace!("Requesting local model list from Ollama server...");
     let model_list = match ollama.list_local_models().await {
-        Ok(m) => m,
+        Ok(m) => {
+            debug!("Successfully retrieved {} models from Ollama server", m.len());
+            trace!("Local models available: {:?}", m.iter().map(|model| &model.name).collect::<Vec<_>>());
+            m
+        }
         Err(e) => {
-            ctx.say(format!("Error: Failed to connect to Ollama: {}", e)).await?;
+            error!("Failed to connect to Ollama server at {}: {}", formatted_host, e);
+            let err_msg = format!("Error: Failed to connect to Ollama: {}", e);
+            trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+            ctx.say(err_msg).await?;
             return Ok(());
         }
     };
 
     let mut needs_create = true;
     let yesterday = Utc::now() - chrono::Duration::days(1);
+    trace!("Checking model list against yesterday's cutoff timestamp ({})", yesterday);
 
     for model in &model_list {
+        trace!("Inspecting model entry: '{}', modified_at: '{}'", model.name, model.modified_at);
         if model.name.starts_with("EwiAI") {
-            if let Ok(modified) = DateTime::parse_from_rfc3339(&model.modified_at) {
+            debug!("Found matching model candidate: '{}'", model.name);
-                if modified.with_timezone(&Utc) > yesterday {
+            match DateTime::parse_from_rfc3339(&model.modified_at) {
-                    needs_create = false;
+                Ok(modified) => {
+                    let modified_utc = modified.with_timezone(&Utc);
+                    trace!("Parsed model modified_at: {} (UTC: {})", modified, modified_utc);
+                    if modified_utc > yesterday {
+                        info!("Model '{}' is up to date (modified {} > cutoff {})", model.name, modified_utc, yesterday);
+                        needs_create = false;
+                    } else {
+                        trace!("Model '{}' was modified at {}, which is older than cutoff {}", model.name, modified_utc, yesterday);
+                    }
+                }
+                Err(e) => {
+                    warn!("Failed to parse modified_at date '{}' for model '{}': {}", model.modified_at, model.name, e);
                 }
             }
         }
     }
 
     if needs_create {
+        info!("EwiAI model is missing or out of date. Initiating model creation/update...");
         let system_prompt = system_prompt();
-        let _ = ctx.say("EwiAI model is missing or out of date. Creating/updating model (this may take a bit)...").await?;
+        trace!("Generated system prompt for model creation (length: {} chars)", system_prompt.len());
+        trace!("System prompt content: {}", system_prompt);
+        let notice_msg = "EwiAI model is missing or out of date. Creating/updating model (this may take a bit)...";
+        trace_message(notice_msg.to_string(), channel_str.clone(), guild_str.clone()).await;
+        let _ = ctx.say(notice_msg).await?;
+
+        trace!("Sending create_model request to Ollama for 'EwiAI' based on 'gemma4:e2b-it-qat'...");
         if let Err(e) = ollama.create_model(CreateModelRequest::new("EwiAI".into())
             .system(system_prompt.into())
             .from_model("gemma4:e2b-it-qat".into())).await {
-            ctx.say(format!("Error creating model: {}", e)).await?;
+            error!("Failed to create model EwiAI: {}", e);
+            let err_msg = format!("Error creating model: {}", e);
+            trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+            ctx.say(err_msg).await?;
             return Ok(());
         }
+        info!("Successfully created/updated EwiAI model");
+    } else {
+        trace!("Skipping model creation; existing model is up to date.");
     }
 
     let mut final_prompt = String::new();
     if let Some(mut limit) = include_messages {
+        trace!("include_messages specified: {}", limit);
         if limit > 10 {
+            trace!("Clamping include_messages limit from {} to 10", limit);
             limit = 10;
         }
+        trace!("Fetching last {} messages from channel {}", limit, channel_str);
         match ctx.channel_id().messages(ctx.http(), poise::serenity_prelude::GetMessages::new().limit(limit)).await {
             Ok(msgs) => {
+                debug!("Retrieved {} messages from channel {}", msgs.len(), channel_str);
                 final_prompt.push_str("Recent channel messages:\n");
                 for msg in msgs.iter().rev() {
                     let mut content = msg.content.clone();
@@ -85,24 +139,38 @@ pub async fn prompt(
                         content.truncate(100);
                         content.push_str("...");
                     }
+                    trace!("Appending message from author {} (ID: {}): snippet='{}'", msg.author.name, msg.author.id, content);
                     final_prompt.push_str(&format!("{} (ID: {}): {}\n", msg.author.name, msg.author.id, content));
                 }
                 final_prompt.push_str("\n");
             }
             Err(e) => {
-                error!("Failed to get messages: {:?}", e);
+                error!("Failed to get messages from channel {}: {:?}", channel_str, e);
             }
         }
     }
     
     final_prompt.push_str(&format!("The user talking to you is {} (ID: {}).\nThat user is telling you the following: {}", ctx.author().name, ctx.author().id, prompt));
+    trace!("Final prompt assembled (length: {} chars)", final_prompt.len());
     trace!("Final prompt: {}", final_prompt);
 
-    let reply = ctx.say("Thinking...\n-# The hardware this thing runs is really slow, expect a long wait").await?;
+    let thinking_msg = "Thinking...\n-# The hardware this thing runs is really slow, expect a long wait";
-    let mut stream = match ollama.generate_stream(GenerationRequest::new("EwiAI".into(), final_prompt).system(system_prompt())).await {
+    trace_message(thinking_msg.to_string(), channel_str.clone(), guild_str.clone()).await;
-        Ok(s) => s,
+    trace!("Sending initial thinking message...");
+    let reply = ctx.say(thinking_msg).await?;
+
+    let sys_prompt = system_prompt();
+    trace!("Generating stream from Ollama model 'EwiAI' with system prompt length {}...", sys_prompt.len());
+    let mut stream = match ollama.generate_stream(GenerationRequest::new("EwiAI".into(), final_prompt).system(sys_prompt)).await {
+        Ok(s) => {
+            debug!("Successfully initiated generation stream");
+            s
+        }
         Err(e) => {
-            reply.edit(ctx, CreateReply::default().content(format!("Error during generation: {}", e))).await?;
+            error!("Error starting generation stream with Ollama: {}", e);
+            let err_msg = format!("Error during generation: {}", e);
+            trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+            reply.edit(ctx, CreateReply::default().content(err_msg)).await?;
             return Ok(());
         }
     };
@@ -110,28 +178,39 @@ pub async fn prompt(
     let mut response_text = String::new();
     let mut last_update = std::time::Instant::now();
     let mut final_response = None;
+    let mut chunk_count = 0usize;
 
+    trace!("Reading chunks from generation stream...");
     while let Some(res) = stream.next().await {
         match res {
             Ok(chunks) => {
+                chunk_count += chunks.len();
+                trace!("Received stream batch containing {} chunk(s)", chunks.len());
                 for chunk in chunks {
+                    trace!("Chunk response segment: '{}', done: {}", chunk.response, chunk.done);
                     response_text.push_str(&chunk.response);
                     if chunk.done {
+                        debug!("Stream chunk marked done");
                         final_response = Some(chunk);
                     }
                 }
 
                 if last_update.elapsed() >= Duration::from_secs(1) && !response_text.is_empty() {
+                    trace!("Throttled stream update: updating reply message (response_text length: {} chars)...", response_text.len());
                     let _ = reply.edit(ctx, CreateReply::default().content(&response_text)).await;
                     last_update = std::time::Instant::now();
                 }
             }
             Err(e) => {
-                let _ = reply.edit(ctx, CreateReply::default().content(format!("{} [Stream Error: {}]", response_text, e))).await;
+                error!("Error encountered while reading stream chunk: {}", e);
+                let err_msg = format!("{} [Stream Error: {}]", response_text, e);
+                trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+                let _ = reply.edit(ctx, CreateReply::default().content(err_msg)).await;
                 return Ok(());
             }
         }
     }
+    info!("Stream completed. Total chunks received: {}, output length: {} chars", chunk_count, response_text.len());
 
     if let Some(stats) = final_response {
         let total_duration = stats.total_duration.unwrap_or(0) as f64 / 1_000_000_000.0;
@@ -139,14 +218,21 @@ pub async fn prompt(
         let eval_duration = stats.eval_duration.unwrap_or(0) as f64 / 1_000_000_000.0;
         let tokens_per_sec = if eval_duration > 0.0 { eval_count as f64 / eval_duration } else { 0.0 };
 
+        debug!("Generation stats: total_duration={:.2}s, eval_count={}, eval_duration={:.2}s, tok/s={:.2}", total_duration, eval_count, eval_duration, tokens_per_sec);
+
         let stats_text = format!(
             "\n\n*Generated in {:.2}s ({:.2} tok/s)*",
             total_duration, tokens_per_sec
         );
         response_text.push_str(&stats_text);
+    } else {
+        trace!("No final response stats available from stream");
     }
     
+    trace_message(response_text.clone(), channel_str.clone(), guild_str.clone()).await;
+    trace!("Sending final edit to reply message...");
     let _ = reply.edit(ctx, CreateReply::default().content(&response_text)).await;
+    debug!("prompt command finished successfully for user {}", ctx.author().name);
 
     Ok(())
 }
@@ -158,66 +244,119 @@ pub async fn answer(
     #[description = "How many messages to include (max 10)"]
     messages_count: Option<u8>,
 ) -> Result<(), Error> {
-    debug!("{} has requested EwiAI to answer", ctx.author().name);
+    let channel_str = ctx.channel_id().to_string();
+    let guild_str = ctx.guild_id().map_or_else(|| "DM".to_string(), |g| g.to_string());
 
+    trace!("answer command called by user {} (ID: {}) in channel {} (guild: {})", ctx.author().name, ctx.author().id, channel_str, guild_str);
+    debug!("{} has requested EwiAI to answer (messages_count: {:?})", ctx.author().name, messages_count);
+
+    trace!("Checking environment variable TG_BOT_OLLAMA_HOST...");
     let host = match env::var("TG_BOT_OLLAMA_HOST") {
-        Ok(h) => h,
+        Ok(h) => {
-        Err(_) => {
+            trace!("Successfully retrieved TG_BOT_OLLAMA_HOST = {}", h);
-            ctx.say("Error: Expected an ollama url in the environment (`TG_BOT_OLLAMA_HOST`).").await?;
+            h
+        }
+        Err(e) => {
+            warn!("TG_BOT_OLLAMA_HOST environment variable missing: {}", e);
+            let err_msg = "Error: Expected an ollama url in the environment (`TG_BOT_OLLAMA_HOST`).";
+            trace_message(err_msg.to_string(), channel_str.clone(), guild_str.clone()).await;
+            ctx.say(err_msg).await?;
             return Ok(());
         }
     };
 
     let formatted_host = if !host.starts_with("http://") && !host.starts_with("https://") {
-        format!("http://{}", host)
+        let f = format!("http://{}", host);
+        trace!("Formatted Ollama host address to include http:// prefix: {}", f);
+        f
     } else {
+        trace!("Ollama host address already has URL scheme: {}", host);
         host
     };
 
+    trace!("Building Ollama client instance for host {} on port 11434...", formatted_host);
     let ollama = Ollama::builder()
         .host(&formatted_host)
         .port(11434)
         .build();
 
+    trace!("Requesting local model list from Ollama server...");
     let model_list = match ollama.list_local_models().await {
-        Ok(m) => m,
+        Ok(m) => {
+            debug!("Successfully retrieved {} models from Ollama server", m.len());
+            trace!("Local models available: {:?}", m.iter().map(|model| &model.name).collect::<Vec<_>>());
+            m
+        }
         Err(e) => {
-            ctx.say(format!("Error: Failed to connect to Ollama: {}", e)).await?;
+            error!("Failed to connect to Ollama server at {}: {}", formatted_host, e);
+            let err_msg = format!("Error: Failed to connect to Ollama: {}", e);
+            trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+            ctx.say(err_msg).await?;
             return Ok(());
         }
     };
 
     let mut needs_create = true;
     let yesterday = Utc::now() - chrono::Duration::days(1);
+    trace!("Checking model list against yesterday's cutoff timestamp ({})", yesterday);
 
     for model in &model_list {
+        trace!("Inspecting model entry: '{}', modified_at: '{}'", model.name, model.modified_at);
         if model.name.starts_with("EwiAI") {
-            if let Ok(modified) = DateTime::parse_from_rfc3339(&model.modified_at) {
+            debug!("Found matching model candidate: '{}'", model.name);
-                if modified.with_timezone(&Utc) > yesterday {
+            match DateTime::parse_from_rfc3339(&model.modified_at) {
-                    needs_create = false;
+                Ok(modified) => {
+                    let modified_utc = modified.with_timezone(&Utc);
+                    trace!("Parsed model modified_at: {} (UTC: {})", modified, modified_utc);
+                    if modified_utc > yesterday {
+                        info!("Model '{}' is up to date (modified {} > cutoff {})", model.name, modified_utc, yesterday);
+                        needs_create = false;
+                    } else {
+                        trace!("Model '{}' was modified at {}, which is older than cutoff {}", model.name, modified_utc, yesterday);
+                    }
+                }
+                Err(e) => {
+                    warn!("Failed to parse modified_at date '{}' for model '{}': {}", model.modified_at, model.name, e);
                 }
             }
         }
     }
 
     if needs_create {
+        info!("EwiAI model is missing or out of date. Initiating model creation/update...");
         let system_prompt = system_prompt();
-        let _ = ctx.say("EwiAI model is missing or out of date. Creating/updating model (this may take a bit)...").await?;
+        trace!("Generated system prompt for model creation (length: {} chars)", system_prompt.len());
+        trace!("System prompt content: {}", system_prompt);
+        let notice_msg = "EwiAI model is missing or out of date. Creating/updating model (this may take a bit)...";
+        trace_message(notice_msg.to_string(), channel_str.clone(), guild_str.clone()).await;
+        let _ = ctx.say(notice_msg).await?;
+
+        trace!("Sending create_model request to Ollama for 'EwiAI' based on 'gemma4:e2b-it-qat'...");
         if let Err(e) = ollama.create_model(CreateModelRequest::new("EwiAI".into())
             .system(system_prompt.into())
             .from_model("gemma4:e2b-it-qat".into())).await {
-            ctx.say(format!("Error creating model: {}", e)).await?;
+            error!("Failed to create model EwiAI: {}", e);
+            let err_msg = format!("Error creating model: {}", e);
+            trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+            ctx.say(err_msg).await?;
             return Ok(());
         }
+        info!("Successfully created/updated EwiAI model");
+    } else {
+        trace!("Skipping model creation; existing model is up to date.");
     }
 
     let mut final_prompt = String::new();
     let mut limit = messages_count.unwrap_or(5);
+    trace!("messages_count limit: {}", limit);
     if limit > 10 {
+        trace!("Clamping messages_count limit from {} to 10", limit);
         limit = 10;
     }
+    trace!("Fetching last {} messages from channel {}", limit, channel_str);
     match ctx.channel_id().messages(ctx.http(), poise::serenity_prelude::GetMessages::new().limit(limit)).await {
         Ok(msgs) => {
+            debug!("Retrieved {} messages from channel {}", msgs.len(), channel_str);
             final_prompt.push_str("Recent channel messages:\n");
             for msg in msgs.iter().rev() {
                 let mut content = msg.content.clone();
@@ -225,23 +364,37 @@ pub async fn answer(
                     content.truncate(100);
                     content.push_str("...");
                 }
+                trace!("Appending message from author {} (ID: {}): snippet='{}'", msg.author.name, msg.author.id, content);
                 final_prompt.push_str(&format!("{} (ID: {}): {}\n", msg.author.name, msg.author.id, content));
             }
             final_prompt.push_str("\n");
         }
         Err(e) => {
-            error!("Failed to get messages: {:?}", e);
+            error!("Failed to get messages from channel {}: {:?}", channel_str, e);
         }
     }
     
-    final_prompt.push_str(&format!("Please respond to the messages above."));
+    final_prompt.push_str("Please respond to the messages above.");
+    trace!("Final prompt assembled (length: {} chars)", final_prompt.len());
     trace!("Final prompt: {}", final_prompt);
 
-    let reply = ctx.say("Thinking...\n-# The hardware this thing runs is really slow, expect a long wait").await?;
+    let thinking_msg = "Thinking...\n-# The hardware this thing runs is really slow, expect a long wait";
-    let mut stream = match ollama.generate_stream(GenerationRequest::new("EwiAI".into(), final_prompt).system(system_prompt())).await {
+    trace_message(thinking_msg.to_string(), channel_str.clone(), guild_str.clone()).await;
-        Ok(s) => s,
+    trace!("Sending initial thinking message...");
+    let reply = ctx.say(thinking_msg).await?;
+
+    let sys_prompt = system_prompt();
+    trace!("Generating stream from Ollama model 'EwiAI' with system prompt length {}...", sys_prompt.len());
+    let mut stream = match ollama.generate_stream(GenerationRequest::new("EwiAI".into(), final_prompt).system(sys_prompt)).await {
+        Ok(s) => {
+            debug!("Successfully initiated generation stream");
+            s
+        }
         Err(e) => {
-            reply.edit(ctx, CreateReply::default().content(format!("Error during generation: {}", e))).await?;
+            error!("Error starting generation stream with Ollama: {}", e);
+            let err_msg = format!("Error during generation: {}", e);
+            trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+            reply.edit(ctx, CreateReply::default().content(err_msg)).await?;
             return Ok(());
         }
     };
@@ -249,28 +402,39 @@ pub async fn answer(
     let mut response_text = String::new();
     let mut last_update = std::time::Instant::now();
     let mut final_response = None;
+    let mut chunk_count = 0usize;
 
+    trace!("Reading chunks from generation stream...");
     while let Some(res) = stream.next().await {
         match res {
             Ok(chunks) => {
+                chunk_count += chunks.len();
+                trace!("Received stream batch containing {} chunk(s)", chunks.len());
                 for chunk in chunks {
+                    trace!("Chunk response segment: '{}', done: {}", chunk.response, chunk.done);
                     response_text.push_str(&chunk.response);
                     if chunk.done {
+                        debug!("Stream chunk marked done");
                         final_response = Some(chunk);
                     }
                 }
 
                 if last_update.elapsed() >= Duration::from_secs(1) && !response_text.is_empty() {
+                    trace!("Throttled stream update: updating reply message (response_text length: {} chars)...", response_text.len());
                     let _ = reply.edit(ctx, CreateReply::default().content(&response_text)).await;
                     last_update = std::time::Instant::now();
                 }
             }
             Err(e) => {
-                let _ = reply.edit(ctx, CreateReply::default().content(format!("{} [Stream Error: {}]", response_text, e))).await;
+                error!("Error encountered while reading stream chunk: {}", e);
+                let err_msg = format!("{} [Stream Error: {}]", response_text, e);
+                trace_message(err_msg.clone(), channel_str.clone(), guild_str.clone()).await;
+                let _ = reply.edit(ctx, CreateReply::default().content(err_msg)).await;
                 return Ok(());
             }
         }
     }
+    info!("Stream completed. Total chunks received: {}, output length: {} chars", chunk_count, response_text.len());
 
     if let Some(stats) = final_response {
         let total_duration = stats.total_duration.unwrap_or(0) as f64 / 1_000_000_000.0;
@@ -278,18 +442,29 @@ pub async fn answer(
         let eval_duration = stats.eval_duration.unwrap_or(0) as f64 / 1_000_000_000.0;
         let tokens_per_sec = if eval_duration > 0.0 { eval_count as f64 / eval_duration } else { 0.0 };
 
+        debug!("Generation stats: total_duration={:.2}s, eval_count={}, eval_duration={:.2}s, tok/s={:.2}", total_duration, eval_count, eval_duration, tokens_per_sec);
+
         let stats_text = format!(
             "\n\n*Generated in {:.2}s ({:.2} tok/s)*",
             total_duration, tokens_per_sec
         );
         response_text.push_str(&stats_text);
+    } else {
+        trace!("No final response stats available from stream");
     }
     
+    trace_message(response_text.clone(), channel_str.clone(), guild_str.clone()).await;
+    trace!("Sending final edit to reply message...");
     let _ = reply.edit(ctx, CreateReply::default().content(&response_text)).await;
+    debug!("answer command finished successfully for user {}", ctx.author().name);
 
     Ok(())
 }
 
 fn system_prompt() -> String {
-    format!("You are EwiAI, an AI in the TeenGovernment Development Server. Your developer is Ewi/ewenlau (discord user id: 713354021124964422, discord username: ewenlau). Be slightly unhelpful, in a sarcastic way, but still answer the question. The current date is {}", Utc::now().to_string())
+    let now_str = Utc::now().to_string();
+    trace!("Generating system_prompt with current UTC timestamp: {}", now_str);
+    let prompt = format!("You are EwiAI, an AI in the TeenGovernment Development Server. Your developer is Ewi/ewenlau (discord user id: 713354021124964422, discord username: ewenlau). Be slightly unhelpful, in a sarcastic way, but still answer the question. The current date is {}", now_str);
+    trace!("Generated system prompt: {}", prompt);
+    prompt
 }