Commit `e16b76f79a98`

Vincent Demeester <vincent@sbr.pm>

2026-02-16 15:03:10

Add comprehensive logging for debugging

Enhanced logging throughout the bot for better observability: **Agent logging:** - Model selection and switching - Tool availability on agent creation - Turn start/end events - Message processing time - Response size **Tool logging:** - Tool execution start/end - Parameters passed to tool - Execution time - Result preview - Tool details (search count, etc.) - Error logging with timing **Main handler logging:** - Better timestamps with arrows (← incoming, → outgoing, ✗ errors) - Total request time - Error details - Agent creation events **Debug mode:** - Pass debug flag through to agent and tools - Tool logging wrapper (withLogging) - Detailed timing information - Parameter inspection Example output with debug=true: [2026-02-16T14:00:00.000Z] ← Message from user@xmpp: Research quantum computing [Main] Creating new agent for JID: user@xmpp [Agent:user@xmpp] Created with model: google/gemini-2.0-flash [Agent:user@xmpp] Tools available: status, web_search, research [Agent:user@xmpp] Processing message with model: google/gemini-2.0-flash [Agent:user@xmpp] Turn started [Tool:research] Starting execution [Tool:research] Parameters: {"topic": "quantum computing"} [Tool:web_search] Starting execution [Tool:web_search] Completed in 234ms [Tool:research] Completed in 1543ms [Agent:user@xmpp] Turn ended (1 tool calls) [Agent:user@xmpp] Response generated in 1850ms (456 chars) [2026-02-16T14:00:02.000Z] → Response sent (456 chars, 2100ms total) Makes debugging much easier!

feature/pi-refactor

1 parent 76fed6d

Changed files (2)

src

tools

logging.ts

agent-wrapper.ts

@@ -0,0 +1,48 @@
+/**
+ * Tool logging wrapper
+ * Wraps tools to add execution logging
+ */
+
+import type { AgentTool } from "@mariozechner/pi-agent-core";
+
+/**
+ * Wrap a tool with logging
+ */
+export function withLogging(tool: AgentTool, debug: boolean = false): AgentTool {
+  if (!debug) {
+    return tool; // No wrapping if debug disabled
+  }
+
+  return {
+    ...tool,
+    execute: async (toolCallId, params, signal, onUpdate) => {
+      const startTime = Date.now();
+      
+      console.log(`[Tool:${tool.name}] Starting execution`);
+      console.log(`[Tool:${tool.name}] Parameters:`, JSON.stringify(params, null, 2));
+      
+      try {
+        const result = await tool.execute(toolCallId, params, signal, onUpdate);
+        
+        const elapsed = Date.now() - startTime;
+        const resultText = result.content
+          .filter((c: any) => c.type === "text")
+          .map((c: any) => c.text)
+          .join(" ");
+        
+        console.log(`[Tool:${tool.name}] Completed in ${elapsed}ms`);
+        console.log(`[Tool:${tool.name}] Result preview: ${resultText.slice(0, 100)}${resultText.length > 100 ? "..." : ""}`);
+        
+        if (result.details) {
+          console.log(`[Tool:${tool.name}] Details:`, JSON.stringify(result.details, null, 2));
+        }
+        
+        return result;
+      } catch (error) {
+        const elapsed = Date.now() - startTime;
+        console.error(`[Tool:${tool.name}] Failed after ${elapsed}ms:`, error);
+        throw error;
+      }
+    },
+  };
+}

@@ -32,11 +32,18 @@ export class XmppAgent {
   private agent: Agent;
   private currentModel: Model<any>;
   private tools: AgentTool[];
+  private debug: boolean;
 
-  constructor(jid: string, defaultModel: Model<any>, tools: AgentTool[] = []) {
+  constructor(jid: string, defaultModel: Model<any>, tools: AgentTool[] = [], debug: boolean = false) {
     this.jid = jid;
     this.currentModel = defaultModel;
     this.tools = tools;
+    this.debug = debug;
+    
+    if (debug) {
+      console.log(`[Agent:${jid}] Created with model: ${defaultModel.provider}/${defaultModel.id}`);
+      console.log(`[Agent:${jid}] Tools available: ${tools.map(t => t.name).join(", ")}`);
+    }
     
     // Initialize Pi Agent
     this.agent = new Agent({
@@ -47,6 +54,18 @@ export class XmppAgent {
         messages: [],
       },
     });
+
+    // Subscribe to agent events for logging
+    if (debug) {
+      this.agent.subscribe((event) => {
+        if (event.type === "turn_start") {
+          console.log(`[Agent:${jid}] Turn started`);
+        } else if (event.type === "turn_end") {
+          const toolCalls = event.toolResults?.length || 0;
+          console.log(`[Agent:${jid}] Turn ended (${toolCalls} tool calls)`);
+        }
+      });
+    }
   }
 
   /**
@@ -54,8 +73,13 @@ export class XmppAgent {
    * Handles slash commands and model prefixes
    */
   async processMessage(body: string): Promise<string> {
+    const startTime = Date.now();
+    
     // Handle slash commands
     if (body.startsWith("/")) {
+      if (this.debug) {
+        console.log(`[Agent:${this.jid}] Processing slash command: ${body}`);
+      }
       return this.handleCommand(body);
     }
 
@@ -66,16 +90,30 @@ export class XmppAgent {
     if (prefix) {
       const newModel = getModelByPrefix(prefix);
       if (newModel) {
+        if (this.debug) {
+          console.log(`[Agent:${this.jid}] Switching model: ${this.currentModel.provider}/${this.currentModel.id} → ${newModel.provider}/${newModel.id}`);
+        }
         this.currentModel = newModel;
         this.agent.setModel(newModel);
       }
     }
 
+    if (this.debug) {
+      console.log(`[Agent:${this.jid}] Processing message with model: ${this.currentModel.provider}/${this.currentModel.id}`);
+    }
+
     // Send message to agent
     await this.agent.prompt(content);
 
     // Get last assistant message
-    return this.getLastAssistantMessage();
+    const response = this.getLastAssistantMessage();
+    
+    const elapsed = Date.now() - startTime;
+    if (this.debug) {
+      console.log(`[Agent:${this.jid}] Response generated in ${elapsed}ms (${response.length} chars)`);
+    }
+    
+    return response;
   }
 
   /**

Commit e16b76f79a98

Commit `e16b76f79a98`