Browse Source

feat(evals): show child agent execution in non-debug mode

- Enable MultiAgentLogger in both debug and non-debug modes
- Add verbose parameter to control output level
- Non-verbose mode shows concise child session lifecycle:
  - Child agent started message
  - Child agent completed with duration
- Verbose mode (--debug) shows full delegation hierarchy
- Update documentation to reflect new behavior

This provides visibility into delegation without overwhelming output,
giving confidence that child agents are actually running.
darrenhinde 7 months ago
parent
commit
0a584ceb57

+ 70 - 1
evals/framework/README.md

@@ -20,7 +20,15 @@ framework/
 │   │   ├── tool-usage-evaluator.ts
 │   │   ├── behavior-evaluator.ts
 │   │   ├── delegation-evaluator.ts
-│   │   └── stop-on-failure-evaluator.ts
+│   │   ├── stop-on-failure-evaluator.ts
+│   │   └── performance-metrics-evaluator.ts  # NEW
+│   ├── logging/             # Multi-agent logging (NEW)
+│   │   ├── types.ts
+│   │   ├── session-tracker.ts
+│   │   ├── logger.ts
+│   │   ├── formatters.ts
+│   │   ├── index.ts
+│   │   └── __tests__/       # 37 unit tests
 │   ├── collector/           # Session data
 │   │   ├── session-reader.ts
 │   │   └── timeline-builder.ts
@@ -56,6 +64,67 @@ Validates complex tasks are delegated to subagents.
 ### stop-on-failure
 Ensures agent stops on errors instead of auto-fixing.
 
+### performance-metrics (NEW)
+Collects performance data for analysis:
+- Total test duration
+- Tool latencies (avg, min, max per tool)
+- LLM inference time estimation
+- Idle time between events
+- Event distribution
+
+Always passes - used for metrics collection only.
+
+## Multi-Agent Logging (NEW)
+
+The framework now includes comprehensive multi-agent logging that tracks delegation hierarchies in real-time.
+
+### Features
+- **Visual hierarchy** - Box characters and indentation show parent-child relationships (debug mode)
+- **Session tracking** - Tracks all sessions (parent, child, grandchild, etc.)
+- **Real-time capture** - Hooks into SDK event stream for live updates
+- **Non-verbose mode** - Shows child agent execution in normal mode without full debug output
+- **Verbose mode** - Full delegation hierarchy with `--debug` flag
+
+### Usage
+```bash
+# Non-verbose mode (default) - shows child agent completion
+npm run eval:sdk -- --agent=openagent --pattern="**/test.yaml"
+
+# Verbose mode (debug) - shows full delegation hierarchy
+npm run eval:sdk -- --agent=openagent --pattern="**/test.yaml" --debug
+```
+
+### Example Output (Non-Verbose Mode)
+```
+Running tests...
+
+   ✓ Child agent completed (OpenAgent, 2.9s)
+
+Running evaluator: approval-gate...
+```
+
+### Example Output (Verbose Mode - Debug)
+```
+┌────────────────────────────────────────────────────────────┐
+│ 🎯 PARENT: OpenAgent (ses_xxx...)                          │
+└────────────────────────────────────────────────────────────┘
+  🔧 TOOL: task
+     ├─ subagent: simple-responder
+     └─ Creating child session...
+
+  ┌────────────────────────────────────────────────────────────┐
+  │ 🎯 CHILD: simple-responder (ses_yyy...)                    │
+  │    Parent: ses_xxx...                                      │
+  │    Depth: 1                                                │
+  └────────────────────────────────────────────────────────────┘
+    🤖 Agent: AWESOME TESTING
+  ✅ CHILD COMPLETE (2.9s)
+
+✅ PARENT COMPLETE (20.9s)
+```
+
+See [src/logging/README.md](src/logging/README.md) for API documentation.
+
 ## Adding an Evaluator
 
 1. Create `src/evaluators/my-evaluator.ts`:

+ 17 - 3
evals/framework/src/logging/README.md

@@ -47,8 +47,9 @@ evals/framework/src/logging/
 ```typescript
 import { MultiAgentLogger } from './logging/index.js';
 
-// Create logger
-const logger = new MultiAgentLogger(true);
+// Create logger (enabled, verbose)
+const logger = new MultiAgentLogger(true, false); // Non-verbose mode
+// const logger = new MultiAgentLogger(true, true); // Verbose mode (debug)
 
 // Log parent session
 logger.logSessionStart('ses_parent_123', 'openagent');
@@ -73,7 +74,7 @@ logger.logSessionComplete('ses_child_456');
 logger.logSessionComplete('ses_parent_123');
 ```
 
-### Output
+### Output (Verbose Mode - Debug)
 
 ```
 ┌────────────────────────────────────────────────────────────┐
@@ -98,6 +99,19 @@ logger.logSessionComplete('ses_parent_123');
 ✅ PARENT COMPLETE (29.4s)
 ```
 
+### Output (Non-Verbose Mode - Default)
+
+```
+Running tests...
+
+   → Child agent started (session: ses_child_45...)
+   ✓ Child agent completed (OpenAgent, 2.5s)
+
+Running evaluator: approval-gate...
+```
+
+In non-verbose mode, only child session lifecycle events are shown, providing visibility into delegation without overwhelming output.
+
 ---
 
 ## API Reference

+ 26 - 8
evals/framework/src/logging/formatters.ts

@@ -119,11 +119,19 @@ export function formatDelegation(
  */
 export function formatChildLinked(
   childSessionId: string,
-  depth: number
+  depth: number,
+  verbose: boolean = false
 ): string {
-  const indent = '  '.repeat(depth + 1);
-  const shortId = childSessionId.substring(0, 12);
-  return `${indent}   └─ Child session: ${shortId}...`;
+  if (verbose) {
+    // Verbose mode: show full details with indentation
+    const indent = '  '.repeat(depth + 1);
+    const shortId = childSessionId.substring(0, 12);
+    return `${indent}   └─ Child session: ${shortId}...`;
+  } else {
+    // Non-verbose mode: show concise message
+    const shortId = childSessionId.substring(0, 12);
+    return `   → Child agent started (session: ${shortId}...)`;
+  }
 }
 
 /**
@@ -132,11 +140,21 @@ export function formatChildLinked(
 export function formatSessionComplete(
   sessionType: 'PARENT' | 'CHILD',
   duration: number,
-  depth: number
+  depth: number,
+  agent?: string,
+  verbose: boolean = false
 ): string {
-  const indent = '  '.repeat(depth);
-  const durationSec = (duration / 1000).toFixed(1);
-  return `${indent}✅ ${sessionType} COMPLETE (${durationSec}s)\n`;
+  if (verbose) {
+    // Verbose mode: show full details with indentation
+    const indent = '  '.repeat(depth);
+    const durationSec = (duration / 1000).toFixed(1);
+    return `${indent}✅ ${sessionType} COMPLETE (${durationSec}s)\n`;
+  } else {
+    // Non-verbose mode: show concise message for child sessions only
+    const durationSec = (duration / 1000).toFixed(1);
+    const agentName = agent || 'child agent';
+    return `   ✓ Child agent completed (${agentName}, ${durationSec}s)`;
+  }
 }
 
 /**

+ 31 - 8
evals/framework/src/logging/logger.ts

@@ -21,10 +21,12 @@ import {
 export class MultiAgentLogger {
   private tracker: SessionTracker;
   private enabled: boolean;
+  private verbose: boolean;
   
-  constructor(enabled = true) {
+  constructor(enabled = true, verbose = false) {
     this.tracker = new SessionTracker();
     this.enabled = enabled;
+    this.verbose = verbose;
   }
   
   /**
@@ -38,8 +40,11 @@ export class MultiAgentLogger {
     
     if (!node) return;
     
-    const header = formatSessionHeader(sessionId, agent, node.depth, parentId);
-    console.log(header);
+    // Only log session headers in verbose mode
+    if (this.verbose) {
+      const header = formatSessionHeader(sessionId, agent, node.depth, parentId);
+      console.log(header);
+    }
   }
   
   /**
@@ -56,8 +61,11 @@ export class MultiAgentLogger {
     const node = this.tracker.getSession(parentSessionId);
     const depth = node?.depth ?? 0;
     
-    const formatted = formatDelegation(toAgent, prompt, depth);
-    console.log(formatted);
+    // Only log delegation details in verbose mode
+    if (this.verbose) {
+      const formatted = formatDelegation(toAgent, prompt, depth);
+      console.log(formatted);
+    }
     
     return delegationId;
   }
@@ -76,7 +84,8 @@ export class MultiAgentLogger {
     const parent = this.tracker.getSession(delegation.parentSessionId);
     const depth = parent?.depth ?? 0;
     
-    const formatted = formatChildLinked(childSessionId, depth);
+    // Always log child session link (important for delegation visibility)
+    const formatted = formatChildLinked(childSessionId, depth, this.verbose);
     console.log(formatted);
   }
   
@@ -86,6 +95,9 @@ export class MultiAgentLogger {
   logMessage(sessionId: string, role: 'user' | 'assistant', text: string): void {
     if (!this.enabled) return;
     
+    // Only log messages in verbose mode
+    if (!this.verbose) return;
+    
     const node = this.tracker.getSession(sessionId);
     const depth = node?.depth ?? 0;
     
@@ -102,6 +114,9 @@ export class MultiAgentLogger {
     // Skip logging task tool (handled by logDelegation)
     if (tool === 'task') return;
     
+    // Only log tool calls in verbose mode
+    if (!this.verbose) return;
+    
     const node = this.tracker.getSession(sessionId);
     const depth = node?.depth ?? 0;
     
@@ -125,8 +140,13 @@ export class MultiAgentLogger {
       : Date.now() - node.startTime;
     
     const sessionType = node.depth === 0 ? 'PARENT' : 'CHILD';
-    const formatted = formatSessionComplete(sessionType, duration, node.depth);
-    console.log(formatted);
+    
+    // Always log child session completion (important for delegation visibility)
+    // Only log parent completion in verbose mode
+    if (sessionType === 'CHILD' || this.verbose) {
+      const formatted = formatSessionComplete(sessionType, duration, node.depth, node.agent, this.verbose);
+      console.log(formatted);
+    }
   }
   
   /**
@@ -135,6 +155,9 @@ export class MultiAgentLogger {
   logSystem(sessionId: string, message: string): void {
     if (!this.enabled) return;
     
+    // Only log system messages in verbose mode
+    if (!this.verbose) return;
+    
     const node = this.tracker.getSession(sessionId);
     const depth = node?.depth ?? 0;
     

+ 86 - 4
evals/framework/src/sdk/test-runner.ts

@@ -32,6 +32,7 @@ import { CleanupConfirmationEvaluator } from '../evaluators/cleanup-confirmation
 import { ExecutionBalanceEvaluator } from '../evaluators/execution-balance-evaluator.js';
 import { BehaviorEvaluator } from '../evaluators/behavior-evaluator.js';
 import { PerformanceMetricsEvaluator } from '../evaluators/performance-metrics-evaluator.js';
+import { AgentModelEvaluator } from '../evaluators/agent-model-evaluator.js';
 import { TestExecutor } from './test-executor.js';
 import { ResultValidator } from './result-validator.js';
 import { createLogger } from './event-logger.js';
@@ -362,11 +363,11 @@ If you see this prompt during a test run, something went wrong with the test set
     this.client = new ClientManager({ baseUrl: url });
     this.eventHandler = new EventStreamHandler(url);
 
-    // Initialize multi-agent logger in debug mode
+    // Initialize multi-agent logger (always enabled, verbose only in debug mode)
+    this.multiAgentLogger = new MultiAgentLogger(true, this.config.debug);
+    this.eventHandler.setMultiAgentLogger(this.multiAgentLogger);
     if (this.config.debug) {
-      this.multiAgentLogger = new MultiAgentLogger(true);
-      this.eventHandler.setMultiAgentLogger(this.multiAgentLogger);
-      console.log('[TestRunner] Multi-agent logging enabled');
+      console.log('[TestRunner] Multi-agent logging enabled (verbose mode)');
     }
 
     // Create executor
@@ -413,6 +414,7 @@ If you see this prompt during a test run, something went wrong with the test set
         new CleanupConfirmationEvaluator(),
         new ExecutionBalanceEvaluator(),
         new PerformanceMetricsEvaluator(),
+        new AgentModelEvaluator({ projectPath: this.config.projectPath }), // Logs agent/model info
       ],
     });
 
@@ -514,12 +516,72 @@ If you see this prompt during a test run, something went wrong with the test set
         const contextEvaluator = new ContextLoadingEvaluator(testCase.behavior);
         this.evaluatorRunner.register(contextEvaluator);
       }
+
+      // If behavior specifies agent/model expectations, replace agent-model evaluator with configured one
+      if (testCase.behavior.expectedAgent || testCase.behavior.expectedModel) {
+        this.logger.log(`Logging agent/model info: ${testCase.behavior.expectedAgent || 'any'} / ${testCase.behavior.expectedModel || 'any'}`);
+        this.evaluatorRunner.unregister('agent-model');
+        const agentModelEvaluator = new AgentModelEvaluator({
+          expectedAgent: testCase.behavior.expectedAgent,
+          expectedModel: testCase.behavior.expectedModel,
+          projectPath: this.config.projectPath,
+        });
+        this.evaluatorRunner.register(agentModelEvaluator);
+      }
     }
     
     try {
       const evaluation = await this.evaluatorRunner.runAll(sessionId);
       this.logger.log(`Evaluators completed: ${evaluation.totalViolations} violations found`);
       
+      // Log agent-model info if available
+      const agentModelResult = evaluation.evaluatorResults.find((r: any) => r.evaluator === 'agent-model');
+      if (agentModelResult && agentModelResult.metadata?.actualAgent) {
+        const agent = agentModelResult.metadata.actualAgent;
+        this.logger.log(`\n${'─'.repeat(60)}`);
+        this.logger.log(`📋 Agent/Model Info:`);
+        this.logger.log(`   Agent: ${agent.name || agent.id || 'unknown'} (${agent.id || 'no-id'})`);
+        this.logger.log(`   Category: ${agent.category || 'unknown'} | Type: ${agent.type || 'unknown'}`);
+        this.logger.log(`   Version: ${agent.version || 'unknown'} | Mode: ${agent.mode || 'unknown'}`);
+        if (agent.description) {
+          this.logger.log(`   Description: ${agent.description}`);
+        }
+        if (agent.promptSnippet) {
+          this.logger.log(`   Prompt: "${agent.promptSnippet.substring(0, 100)}..."`);
+        }
+        if (agentModelResult.metadata.expectedAgent || agentModelResult.metadata.expectedModel) {
+          this.logger.log(`   Expected: ${agentModelResult.metadata.expectedAgent || 'any'} / ${agentModelResult.metadata.expectedModel || 'any'}`);
+        }
+        this.logger.log(`${'─'.repeat(60)}\n`);
+      }
+      
+      // Log delegation info if available
+      const delegationResult = evaluation.evaluatorResults.find((r: any) => r.evaluator === 'delegation');
+      
+      // Check allEvidence for task tool calls
+      const taskToolEvidence = evaluation.allEvidence.find((e: any) => 
+        e.type === 'task-tool-call' || e.description?.includes('Task tool call')
+      );
+      
+      if (taskToolEvidence) {
+        this.logger.log(`\n${'─'.repeat(60)}`);
+        this.logger.log(`🔄 Delegation Summary:`);
+        this.logger.log(`   ${taskToolEvidence.description}`);
+        if (taskToolEvidence.data) {
+          if (taskToolEvidence.data.subagent_type) {
+            this.logger.log(`   Subagent: ${taskToolEvidence.data.subagent_type}`);
+          }
+          if (taskToolEvidence.data.description) {
+            this.logger.log(`   Description: ${taskToolEvidence.data.description}`);
+          }
+          if (taskToolEvidence.data.prompt) {
+            const prompt = taskToolEvidence.data.prompt.substring(0, 150);
+            this.logger.log(`   Prompt: "${prompt}${taskToolEvidence.data.prompt.length > 150 ? '...' : ''}"`);
+          }
+        }
+        this.logger.log(`${'─'.repeat(60)}\n`);
+      }
+      
       if (evaluation && evaluation.totalViolations > 0) {
         this.logger.log(`  Errors: ${evaluation.violationsBySeverity.error}`);
         this.logger.log(`  Warnings: ${evaluation.violationsBySeverity.warning}`);
@@ -534,6 +596,12 @@ If you see this prompt during a test run, something went wrong with the test set
           this.evaluatorRunner.unregister('context-loading');
           this.evaluatorRunner.register(new ContextLoadingEvaluator());
         }
+
+        // Restore default agent-model evaluator if we replaced it
+        if (testCase.behavior.expectedAgent || testCase.behavior.expectedModel) {
+          this.evaluatorRunner.unregister('agent-model');
+          this.evaluatorRunner.register(new AgentModelEvaluator({ projectPath: this.config.projectPath }));
+        }
       }
 
       return evaluation;
@@ -560,6 +628,20 @@ If you see this prompt during a test run, something went wrong with the test set
     if (evaluation) {
       this.logger.log(`Evaluation Score: ${evaluation.overallScore}/100`);
       this.logger.log(`Violations: ${evaluation.totalViolations} (E:${evaluation.violationsBySeverity.error} W:${evaluation.violationsBySeverity.warning})`);
+      
+      // Log violation details if any
+      if (evaluation.totalViolations > 0) {
+        this.logger.log(`\n${'─'.repeat(60)}`);
+        this.logger.log(`⚠️  Violation Details:`);
+        evaluation.allViolations.forEach((v: any, i: number) => {
+          const icon = v.severity === 'error' ? '❌' : v.severity === 'warning' ? '⚠️' : 'ℹ️';
+          this.logger.log(`   ${i + 1}. ${icon} [${v.rule || v.type}] ${v.message}`);
+          if (v.context) {
+            this.logger.log(`      Context: ${JSON.stringify(v.context)}`);
+          }
+        });
+        this.logger.log(`${'─'.repeat(60)}\n`);
+      }
     }
   }