1  /**
  2   * Tests for Structured Logging System
  3   *
  4   * Validates StructuredLogger, agent_outcomes tracking, and learning from past outcomes.
  5   */
  6  
  7  import { test } from 'node:test';
  8  import assert from 'node:assert';
  9  import Database from 'better-sqlite3';
 10  import { mkdtempSync, rmSync } from 'fs';
 11  import { tmpdir } from 'os';
 12  import { join } from 'path';
 13  import StructuredLogger, {
 14    resetDb as resetLoggerDb,
 15  } from '../../src/agents/utils/structured-logger.js';
 16  import { BaseAgent, resetDb as resetBaseDb } from '../../src/agents/base-agent.js';
 17  import { resetDb as resetTaskManagerDb } from '../../src/agents/utils/task-manager.js';
 18  
 19  // Test agent implementation
 20  class TestAgent extends BaseAgent {
 21    constructor() {
 22      super('developer', ['base.md', 'developer.md']);
 23    }
 24  
 25    // Override initialize to skip context loading in tests
 26    async initialize() {
 27      if (this.isInitialized) return;
 28  
 29      // Set dummy context for tests
 30      this.context = 'Test context';
 31      this.contextMetadata = { sizeKB: 0, files: [], context: 'Test context' };
 32  
 33      // Update agent_state
 34      this.updateAgentState('idle');
 35  
 36      this.isInitialized = true;
 37    }
 38  
 39    async processTask(task) {
 40      // Simple test task processing
 41      await this.log('info', 'Processing test task', { task_type: task.task_type });
 42  
 43      if (task.task_type === 'fail_task') {
 44        throw new Error('Intentional test failure');
 45      }
 46  
 47      await this.completeTask(task.id, { success: true });
 48    }
 49  }
 50  
 51  let testDir;
 52  let dbPath;
 53  let db;
 54  
 55  test('Structured Logging System', async t => {
 56    await t.beforeEach(() => {
 57      // Reset database connections first
 58      resetLoggerDb();
 59      resetBaseDb();
 60      resetTaskManagerDb();
 61  
 62      // Create temporary directory and database
 63      testDir = mkdtempSync(join(tmpdir(), 'agent-test-'));
 64      dbPath = join(testDir, 'test.db');
 65      process.env.DATABASE_PATH = dbPath;
 66  
 67      // Initialize database
 68      db = new Database(dbPath);
 69      db.pragma('foreign_keys = ON');
 70      db.pragma('journal_mode = WAL'); // Better concurrency
 71  
 72      // Create required tables
 73      db.exec(`
 74        CREATE TABLE agent_logs (
 75          id INTEGER PRIMARY KEY AUTOINCREMENT,
 76          task_id INTEGER,
 77          agent_name TEXT NOT NULL,
 78          log_level TEXT CHECK(log_level IN ('debug', 'info', 'warn', 'error')),
 79          message TEXT NOT NULL,
 80          data_json TEXT,
 81          created_at DATETIME DEFAULT CURRENT_TIMESTAMP
 82        );
 83  
 84        CREATE TABLE agent_outcomes (
 85          id INTEGER PRIMARY KEY AUTOINCREMENT,
 86          task_id INTEGER NOT NULL,
 87          agent_name TEXT NOT NULL,
 88          task_type TEXT NOT NULL,
 89          outcome TEXT NOT NULL CHECK(outcome IN ('success', 'failure')),
 90          context_json TEXT,
 91          result_json TEXT,
 92          duration_ms INTEGER,
 93          created_at DATETIME DEFAULT CURRENT_TIMESTAMP
 94        );
 95  
 96        CREATE TABLE agent_tasks (
 97          id INTEGER PRIMARY KEY AUTOINCREMENT,
 98          task_type TEXT NOT NULL,
 99          assigned_to TEXT NOT NULL,
100          created_by TEXT,
101          status TEXT DEFAULT 'pending',
102          priority INTEGER DEFAULT 5,
103          context_json TEXT,
104          result_json TEXT,
105          parent_task_id INTEGER,
106          error_message TEXT,
107          created_at DATETIME DEFAULT CURRENT_TIMESTAMP,
108          started_at DATETIME,
109          completed_at DATETIME,
110          retry_count INTEGER DEFAULT 0
111        );
112  
113        CREATE TABLE agent_state (
114          agent_name TEXT PRIMARY KEY,
115          last_active DATETIME DEFAULT CURRENT_TIMESTAMP,
116          current_task_id INTEGER,
117          status TEXT DEFAULT 'idle',
118          metrics_json TEXT
119        );
120      `);
121  
122      // Initialize agent state
123      db.prepare("INSERT INTO agent_state (agent_name, status) VALUES (?, 'idle')").run('developer');
124    });
125  
126    await t.afterEach(() => {
127      // Reset database connections first to release locks
128      resetLoggerDb();
129      resetBaseDb();
130      resetTaskManagerDb();
131  
132      // Close database and clean up
133      if (db) {
134        try {
135          db.close();
136        } catch (e) {
137          // Ignore
138        }
139        db = null;
140      }
141  
142      if (testDir) {
143        try {
144          rmSync(testDir, { recursive: true, force: true });
145        } catch (e) {
146          // Ignore
147        }
148        testDir = null;
149      }
150  
151      // Clear the env var
152      delete process.env.DATABASE_PATH;
153    });
154  
155    await t.test('StructuredLogger - basic functionality', () => {
156      const logger = new StructuredLogger('developer', 123);
157  
158      // Log at different levels
159      logger.info('Test info message', { action: 'test' });
160      logger.warn('Test warning', { warning_type: 'test' });
161      logger.error('Test error', { error_type: 'test' });
162      logger.debug('Test debug', { debug_data: 'test' });
163  
164      // Verify logs written to database
165      const logs = db.prepare('SELECT * FROM agent_logs ORDER BY id ASC').all();
166  
167      assert.strictEqual(logs.length, 4);
168      assert.strictEqual(logs[0].log_level, 'info');
169      assert.strictEqual(logs[0].message, 'Test info message');
170      assert.strictEqual(logs[0].agent_name, 'developer');
171      assert.strictEqual(logs[0].task_id, 123);
172  
173      assert.strictEqual(logs[1].log_level, 'warn');
174      assert.strictEqual(logs[2].log_level, 'error');
175      assert.strictEqual(logs[3].log_level, 'debug');
176    });
177  
178    await t.test('StructuredLogger - JSON context', () => {
179      const logger = new StructuredLogger('qa', 456);
180  
181      logger.info('Task started', {
182        file: 'src/test.js',
183        action: 'verify_fix',
184        metadata: { version: '1.0' },
185      });
186  
187      const log = db.prepare('SELECT * FROM agent_logs WHERE task_id = 456').get();
188  
189      assert.ok(log);
190      assert.ok(log.data_json);
191  
192      const data = JSON.parse(log.data_json);
193      assert.strictEqual(data.file, 'src/test.js');
194      assert.strictEqual(data.action, 'verify_fix');
195      assert.deepStrictEqual(data.metadata, { version: '1.0' });
196    });
197  
198    await t.test('StructuredLogger - without task ID', () => {
199      const logger = new StructuredLogger('security');
200  
201      logger.info('Global security scan started');
202  
203      const log = db.prepare('SELECT * FROM agent_logs WHERE agent_name = ?').get('security');
204  
205      assert.ok(log);
206      assert.strictEqual(log.task_id, null);
207      assert.strictEqual(log.message, 'Global security scan started');
208    });
209  
210    await t.test('StructuredLogger - setTaskId', () => {
211      const logger = new StructuredLogger('architect');
212  
213      logger.info('Agent initialized', { status: 'ready' });
214  
215      // Set task ID after creation
216      logger.setTaskId(789);
217      logger.info('Task assigned', { task_type: 'design_review' });
218  
219      const logs = db
220        .prepare('SELECT * FROM agent_logs WHERE agent_name = ? ORDER BY id')
221        .all('architect');
222  
223      assert.strictEqual(logs.length, 2);
224      assert.strictEqual(logs[0].task_id, null); // Before setTaskId
225      assert.strictEqual(logs[1].task_id, 789); // After setTaskId
226    });
227  
228    await t.test('StructuredLogger - invalid log level', () => {
229      const logger = new StructuredLogger('developer');
230  
231      assert.throws(() => {
232        logger.log('invalid', 'Test message');
233      }, /Invalid log level/);
234    });
235  
236    await t.test('BaseAgent - recordOutcome success', async () => {
237      const agent = new TestAgent();
238      await agent.initialize();
239  
240      // Create a test task
241      const taskId = db
242        .prepare(
243          `
244        INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
245        VALUES (?, ?, ?, ?)
246      `
247        )
248        .run('fix_bug', 'developer', 'triage', 'completed').lastInsertRowid;
249  
250      // Record successful outcome
251      await agent.recordOutcome(
252        taskId,
253        'success',
254        { error_type: 'null_pointer', duration_ms: 1500 },
255        { files_changed: ['src/test.js'], approach: 'Added null check' }
256      );
257  
258      // Verify outcome recorded
259      const outcome = db.prepare('SELECT * FROM agent_outcomes WHERE task_id = ?').get(taskId);
260  
261      assert.ok(outcome);
262      assert.strictEqual(outcome.agent_name, 'developer');
263      assert.strictEqual(outcome.task_type, 'fix_bug');
264      assert.strictEqual(outcome.outcome, 'success');
265      assert.strictEqual(outcome.duration_ms, 1500);
266  
267      const context = JSON.parse(outcome.context_json);
268      assert.strictEqual(context.error_type, 'null_pointer');
269  
270      const result = JSON.parse(outcome.result_json);
271      assert.deepStrictEqual(result.files_changed, ['src/test.js']);
272    });
273  
274    await t.test('BaseAgent - recordOutcome failure', async () => {
275      const agent = new TestAgent();
276      await agent.initialize();
277  
278      // Create a test task
279      const taskId = db
280        .prepare(
281          `
282        INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
283        VALUES (?, ?, ?, ?)
284      `
285        )
286        .run('fix_bug', 'developer', 'triage', 'failed').lastInsertRowid;
287  
288      // Record failure outcome
289      await agent.recordOutcome(
290        taskId,
291        'failure',
292        {
293          error_type: 'database',
294          error: 'UNIQUE constraint failed',
295          duration_ms: 500,
296        },
297        {}
298      );
299  
300      // Verify outcome recorded
301      const outcome = db.prepare('SELECT * FROM agent_outcomes WHERE task_id = ?').get(taskId);
302  
303      assert.ok(outcome);
304      assert.strictEqual(outcome.outcome, 'failure');
305      assert.strictEqual(outcome.duration_ms, 500);
306  
307      const context = JSON.parse(outcome.context_json);
308      assert.strictEqual(context.error_type, 'database');
309      assert.strictEqual(context.error, 'UNIQUE constraint failed');
310    });
311  
312    await t.test('BaseAgent - recordOutcome invalid outcome', async () => {
313      const agent = new TestAgent();
314      await agent.initialize();
315  
316      const taskId = db
317        .prepare(
318          `
319        INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
320        VALUES (?, ?, ?, ?)
321      `
322        )
323        .run('fix_bug', 'developer', 'triage', 'completed').lastInsertRowid;
324  
325      await assert.rejects(async () => {
326        await agent.recordOutcome(taskId, 'invalid', {}, {});
327      }, /Invalid outcome/);
328    });
329  
330    await t.test('BaseAgent - learnFromPastOutcomes no data', async () => {
331      const agent = new TestAgent();
332      await agent.initialize();
333  
334      const insights = await agent.learnFromPastOutcomes('fix_bug');
335  
336      assert.strictEqual(insights.total_outcomes, 0);
337      assert.strictEqual(insights.success_rate, 0);
338      assert.strictEqual(insights.task_type, 'fix_bug');
339      assert.ok(insights.insights.includes('No historical data'));
340    });
341  
342    await t.test('BaseAgent - learnFromPastOutcomes with data', async () => {
343      const agent = new TestAgent();
344      await agent.initialize();
345  
346      // Create test tasks and outcomes
347      const outcomes = [
348        { outcome: 'success', error_type: 'null_pointer', duration: 1000 },
349        { outcome: 'success', error_type: 'null_pointer', duration: 1200 },
350        { outcome: 'failure', error_type: 'database', duration: 500 },
351        { outcome: 'success', error_type: 'network', duration: 2000 },
352        { outcome: 'failure', error_type: 'database', duration: 600 },
353      ];
354  
355      for (const o of outcomes) {
356        const taskId = db
357          .prepare(
358            `
359          INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
360          VALUES (?, ?, ?, ?)
361        `
362          )
363          .run('fix_bug', 'developer', 'triage', 'completed').lastInsertRowid;
364  
365        db.prepare(
366          `
367          INSERT INTO agent_outcomes (task_id, agent_name, task_type, outcome, context_json, duration_ms)
368          VALUES (?, ?, ?, ?, ?, ?)
369        `
370        ).run(
371          taskId,
372          'developer',
373          'fix_bug',
374          o.outcome,
375          JSON.stringify({ error_type: o.error_type }),
376          o.duration
377        );
378      }
379  
380      // Learn from outcomes
381      const insights = await agent.learnFromPastOutcomes('fix_bug');
382  
383      assert.strictEqual(insights.total_outcomes, 5);
384      assert.strictEqual(insights.success_count, 3);
385      assert.strictEqual(insights.failure_count, 2);
386      assert.strictEqual(insights.success_rate, 60);
387  
388      // Check average duration (1000 + 1200 + 500 + 2000 + 600) / 5 = 1060
389      assert.strictEqual(insights.avg_duration_ms, 1060);
390  
391      // Check context patterns
392      assert.ok(insights.context_patterns);
393      assert.ok(insights.context_patterns.null_pointer);
394      assert.strictEqual(insights.context_patterns.null_pointer.total, 2);
395      assert.strictEqual(insights.context_patterns.null_pointer.successes, 2);
396      assert.strictEqual(insights.context_patterns.null_pointer.success_rate, 100);
397  
398      assert.ok(insights.context_patterns.database);
399      assert.strictEqual(insights.context_patterns.database.total, 2);
400      assert.strictEqual(insights.context_patterns.database.successes, 0);
401      assert.strictEqual(insights.context_patterns.database.success_rate, 0);
402  
403      assert.ok(insights.recommendations);
404      assert.ok(Array.isArray(insights.recommendations));
405    });
406  
407    await t.test('BaseAgent - executeTask records outcomes automatically', async () => {
408      const agent = new TestAgent();
409      await agent.initialize();
410  
411      // Create a successful task
412      const successTaskId = db
413        .prepare(
414          `
415        INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
416        VALUES (?, ?, ?, ?)
417      `
418        )
419        .run('test_success', 'developer', 'system', 'pending').lastInsertRowid;
420  
421      const task = db.prepare('SELECT * FROM agent_tasks WHERE id = ?').get(successTaskId);
422  
423      // Execute task (should succeed)
424      await agent.executeTask(task);
425  
426      // Verify success outcome recorded
427      const successOutcome = db
428        .prepare('SELECT * FROM agent_outcomes WHERE task_id = ?')
429        .get(successTaskId);
430  
431      assert.ok(successOutcome);
432      assert.strictEqual(successOutcome.outcome, 'success');
433      assert.strictEqual(successOutcome.task_type, 'test_success');
434      assert.ok(successOutcome.duration_ms > 0);
435    });
436  
437    await t.test('BaseAgent - executeTask records failure outcomes', async () => {
438      const agent = new TestAgent();
439      await agent.initialize();
440  
441      // Create a task that will fail
442      const failTaskId = db
443        .prepare(
444          `
445        INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
446        VALUES (?, ?, ?, ?)
447      `
448        )
449        .run('fail_task', 'developer', 'system', 'pending').lastInsertRowid;
450  
451      const task = db.prepare('SELECT * FROM agent_tasks WHERE id = ?').get(failTaskId);
452  
453      // Execute task (should fail)
454      await assert.rejects(async () => {
455        await agent.executeTask(task);
456      }, /Intentional test failure/);
457  
458      // Verify failure outcome recorded
459      const failOutcome = db
460        .prepare('SELECT * FROM agent_outcomes WHERE task_id = ?')
461        .get(failTaskId);
462  
463      assert.ok(failOutcome);
464      assert.strictEqual(failOutcome.outcome, 'failure');
465      assert.strictEqual(failOutcome.task_type, 'fail_task');
466  
467      const context = JSON.parse(failOutcome.context_json);
468      assert.strictEqual(context.error, 'Intentional test failure');
469      assert.ok(context.stack);
470    });
471  
472    await t.test('BaseAgent - structured logger integration', async () => {
473      const agent = new TestAgent();
474      await agent.initialize();
475  
476      // Create a task
477      const taskId = db
478        .prepare(
479          `
480        INSERT INTO agent_tasks (task_type, assigned_to, created_by, status)
481        VALUES (?, ?, ?, ?)
482      `
483        )
484        .run('test_logging', 'developer', 'system', 'pending').lastInsertRowid;
485  
486      const task = db.prepare('SELECT * FROM agent_tasks WHERE id = ?').get(taskId);
487  
488      // Execute task
489      await agent.executeTask(task);
490  
491      // Verify structured logs created
492      const logs = db.prepare('SELECT * FROM agent_logs WHERE task_id = ? ORDER BY id').all(taskId);
493  
494      assert.ok(logs.length > 0);
495  
496      // Should have at least: Task started, Processing test task, Task completed
497      const messages = logs.map(l => l.message);
498      assert.ok(messages.some(m => m.includes('Task started')));
499      assert.ok(messages.some(m => m.includes('Processing test task')));
500      assert.ok(messages.some(m => m.includes('Task completed')));
501  
502      // All logs should have proper structure
503      for (const log of logs) {
504        assert.strictEqual(log.agent_name, 'developer');
505        assert.strictEqual(log.task_id, taskId);
506        assert.ok(['debug', 'info', 'warn', 'error'].includes(log.log_level));
507      }
508    });
509  });