trace/test/trace.test.js

103 lines
3.7 KiB
JavaScript

'use strict';
const { test } = require('node:test');
const assert = require('node:assert');
const fs = require('fs');
const os = require('os');
const path = require('path');
const { Tracer, replay, summarize } = require('../index.js');
// deterministic clock: increments 10ms per read
function fakeClock(start = 1000, step = 10) {
let t = start;
return () => { const now = t; t += step; return now; };
}
test('events carry run id, timestamp, type', () => {
const t = new Tracer({ run: 'r1', clock: fakeClock() });
t.step('plan', { goal: 'x' });
assert.strictEqual(t.events.length, 1);
const e = t.events[0];
assert.strictEqual(e.run, 'r1');
assert.strictEqual(e.type, 'step');
assert.strictEqual(e.name, 'plan');
assert.strictEqual(typeof e.ts, 'number');
assert.deepStrictEqual(e.data, { goal: 'x' });
});
test('spans record a duration from the injected clock', () => {
const t = new Tracer({ clock: fakeClock(0, 5) }); // 0,5,10,15...
const s = t.start('work'); // clock->0 (start emit reads clock at construct: startedAt=0, emit ts=5)
const ms = s.end(); // end reads clock again
assert.ok(ms > 0, 'duration is positive');
const ends = t.events.filter((e) => e.type === 'span:end');
assert.strictEqual(ends.length, 1);
assert.strictEqual(ends[0].ms, ms);
});
test('nested spans link parent', () => {
const t = new Tracer({ clock: fakeClock() });
const p = t.start('parent');
const c = p.child('child');
c.end();
p.end();
const child = t.events.find((e) => e.type === 'span:start' && e.name === 'child');
assert.strictEqual(child.parent, p.id);
});
test('span() wrapper auto-times and captures a thrown error, then re-throws', async () => {
const t = new Tracer({ clock: fakeClock() });
await assert.rejects(() => t.span('risky', async () => { throw new Error('boom'); }));
const errs = t.events.filter((e) => e.type === 'error');
assert.strictEqual(errs.length, 1);
assert.strictEqual(errs[0].data.message, 'boom');
// the span still closed
assert.strictEqual(t.events.filter((e) => e.type === 'span:end').length, 1);
});
test('span() returns the fn result on success', async () => {
const t = new Tracer({ clock: fakeClock() });
const out = await t.span('ok', async () => 42);
assert.strictEqual(out, 42);
});
test('a live sink receives every event (and a throwing sink never breaks tracing)', () => {
const seen = [];
const t = new Tracer({ clock: fakeClock(), sink: (e) => { seen.push(e.type); if (e.name === 'kaboom') throw new Error('sink'); } });
t.step('a');
t.error('kaboom', {}); // sink throws here — must not propagate
assert.deepStrictEqual(seen, ['step', 'error']);
assert.strictEqual(t.events.length, 2);
});
test('toJSONL round-trips through replay', () => {
const t = new Tracer({ run: 'rr', clock: fakeClock() });
t.step('a'); t.step('b');
const back = replay(t.toJSONL());
assert.strictEqual(back.length, 2);
assert.strictEqual(back[0].name, 'a');
assert.strictEqual(back[1].run, 'rr');
});
test('flush writes a file that replay reads back', () => {
const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'trace-'));
const f = path.join(dir, 'run.jsonl');
const t = new Tracer({ clock: fakeClock() });
t.step('one'); const s = t.start('two'); s.end();
t.flush(f);
const back = replay(f);
assert.ok(back.length >= 3);
fs.rmSync(dir, { recursive: true, force: true });
});
test('summarize reports counts, errors, and slowest spans', () => {
const t = new Tracer({ clock: fakeClock(0, 100) });
const a = t.start('fast'); a.end();
const b = t.start('slow'); b.end();
t.error('oops', {});
const s = summarize(t.events);
assert.strictEqual(s.spans, 2);
assert.strictEqual(s.errors, 1);
assert.ok(s.slowest.length >= 1);
assert.ok(s.total_ms > 0);
});