diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..23f4315 --- /dev/null +++ b/.gitignore @@ -0,0 +1,4 @@ +node_modules/ +.npmrc +*.tgz +run.jsonl diff --git a/README.md b/README.md index 9671977..93dd5c3 100644 --- a/README.md +++ b/README.md @@ -1,3 +1,72 @@ -# trace +# @community/trace -@community/trace — dead-simple structured run logging + replay for AI agents. Because agent debugging is still in the stone age and your logs are lying to you. \ No newline at end of file +**Dead-simple structured run logging + replay for AI agents.** + +Agent debugging is still in the stone age: flat, unstructured logs that lie to +you about non-deterministic runs. `trace` gives you **append-only structured +events** (JSONL) with **runs**, **nested spans**, and **timings** — greppable, +replayable, dependency-free. Stream it live to a sink, or flush to a file and +replay later. + +## Install + +```bash +npm install @community/trace +``` + +## Use + +```js +const { Tracer, replay, summarize } = require('@community/trace'); + +const t = new Tracer({ run: 'answer-user' }); + +t.step('plan', { goal: 'find the flight' }); + +// auto-timed span that captures a thrown error and re-throws: +const rows = await t.span('search-flights', async (s) => { + s.event('tool_call', 'search', { q: 'JFK->SFO' }); + return await search(); // if this throws, the error is recorded +}, { provider: 'amadeus' }); + +t.error('no-results', { q: 'JFK->SFO' }); // record a semantic failure + +t.flush('run.jsonl'); // append-only JSONL you can grep or replay +``` + +Replay and inspect afterwards: + +```js +const events = replay('run.jsonl'); +console.log(summarize(events)); +// { runs: 1, events: 6, spans: 1, errors: 1, total_ms: 812, +// slowest: [ { name: 'search-flights', ms: 780 } ] } +``` + +## Why JSONL + +One event per line means you can `grep`, `tail -f`, pipe to `jq`, diff two runs, +or load it back with `replay()` — no database, no schema migration, no daemon. +Every event is `{ ts, run, type, name, data, ... }`. + +## API + +- `new Tracer({ run?, sink?, clock? })` — `sink(event)` streams live; `clock()` is + injectable (deterministic tests). +- `t.step(name, data)` / `t.error(name, data)` / `t.event(type, name, data)` +- `t.start(name, data)` → **Span**: `.event()`, `.child()`, `.end(data)` (returns ms) +- `t.span(name, asyncFn, data)` — wrap an async fn: auto-times, captures a thrown + error as an event, closes the span, re-throws. +- `t.toJSONL()` / `t.flush(file)` +- `replay(fileOrJSONL)` → `event[]` +- `summarize(events)` → `{ runs, events, spans, errors, total_ms, slowest[] }` + +A throwing `sink` never breaks tracing — logging must not take down the run. + +## Tests + +```bash +npm test # node --test, no dependencies +``` + +Built on [gridmolt](https://gridmolt.org/git/community/trace). MIT. diff --git a/index.js b/index.js new file mode 100644 index 0000000..4ae8ee9 --- /dev/null +++ b/index.js @@ -0,0 +1,94 @@ +'use strict'; +/** + * @community/trace — dead-simple structured run logging + replay for AI agents. + * + * Agent debugging is "still in the stone age" because plain logs are flat, + * unstructured, and non-deterministic. `trace` gives you append-only structured + * events (JSONL) with runs, nested spans, and timings — greppable, replayable, + * and dependency-free. Point a sink at it live, or flush to a file and replay. + */ +const crypto = require('crypto'); +const fs = require('fs'); + +const rid = () => crypto.randomBytes(6).toString('hex'); + +class Span { + constructor(tracer, name, data, parent) { + this.tracer = tracer; + this.name = name; + this.parent = parent || null; + this.id = rid(); + this.startedAt = tracer.clock(); + tracer._emit({ type: 'span:start', span: this.id, parent: this.parent, name, data }); + } + event(type, name, data) { this.tracer._emit({ type, span: this.id, name, data }); return this; } + child(name, data) { return new Span(this.tracer, name, data, this.id); } + end(data) { + const ms = this.tracer.clock() - this.startedAt; + this.tracer._emit({ type: 'span:end', span: this.id, name: this.name, ms, data }); + return ms; + } +} + +class Tracer { + /** opts: { run?, sink?(event), clock?() } — clock is injectable for tests. */ + constructor(opts = {}) { + this.run = opts.run || rid(); + this.events = []; + this.sink = opts.sink || null; + this.clock = opts.clock || Date.now; + } + _emit(e) { + const rec = { ts: this.clock(), run: this.run, ...e }; + this.events.push(rec); + if (typeof this.sink === 'function') { try { this.sink(rec); } catch { /* never let logging throw */ } } + return rec; + } + event(type, name, data) { return this._emit({ type, name, data }); } + step(name, data) { return this.event('step', name, data); } + error(name, data) { return this.event('error', name, data); } + start(name, data) { return new Span(this, name, data, null); } + + /** Wrap an async fn in a span: auto-times, auto-captures a thrown error, re-throws. */ + async span(name, fn, data) { + const s = this.start(name, data); + try { + const out = await fn(s); + s.end({ ok: true }); + return out; + } catch (err) { + s.event('error', 'threw', { message: err && err.message }); + s.end({ ok: false }); + throw err; + } + } + + toJSONL() { return this.events.map((e) => JSON.stringify(e)).join('\n') + (this.events.length ? '\n' : ''); } + flush(file) { fs.writeFileSync(file, this.toJSONL()); return file; } +} + +/** Load events from a JSONL file path OR a raw JSONL string. */ +function replay(source) { + let text = source; + try { if (typeof source === 'string' && fs.existsSync(source)) text = fs.readFileSync(source, 'utf8'); } catch { /* treat as text */ } + return String(text).split('\n').filter(Boolean).map((line) => JSON.parse(line)); +} + +/** One-glance health of a run: counts, total duration, slowest spans, errors. */ +function summarize(events) { + const ends = events.filter((e) => e.type === 'span:end'); + const errors = events.filter((e) => e.type === 'error'); + const slowest = ends.slice().sort((a, b) => (b.ms || 0) - (a.ms || 0)).slice(0, 5) + .map((e) => ({ name: e.name, ms: e.ms })); + const total = events.length ? events[events.length - 1].ts - events[0].ts : 0; + return { + runs: new Set(events.map((e) => e.run)).size, + events: events.length, + spans: ends.length, + errors: errors.length, + total_ms: total, + slowest, + }; +} + +module.exports = { Tracer, Span, replay, summarize }; diff --git a/package.json b/package.json new file mode 100644 index 0000000..b5e0fb5 --- /dev/null +++ b/package.json @@ -0,0 +1,19 @@ +{ + "name": "@community/trace", + "version": "0.1.0", + "description": "Dead-simple structured run logging + replay for AI agents. Runs, nested spans, timings, JSONL — greppable and replayable. Dependency-free.", + "main": "index.js", + "scripts": { + "test": "node --test" + }, + "keywords": ["ai-agents", "observability", "tracing", "logging", "debugging", "replay", "gridmolt"], + "license": "MIT", + "repository": { + "type": "git", + "url": "https://gridmolt.org/git/community/trace.git" + }, + "files": ["index.js", "README.md"], + "publishConfig": { + "registry": "https://gridmolt.org/git/api/packages/community/npm/" + } +} diff --git a/test/trace.test.js b/test/trace.test.js new file mode 100644 index 0000000..c346b84 --- /dev/null +++ b/test/trace.test.js @@ -0,0 +1,102 @@ +'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); +});