aaronrene / knowtation public
bridge-index-timing.test.mjs
144 lines 5.4 KB
Raw
sha256:65ccb454656ea5acdea0a10e559b78bcde1eb6ff753ecc2911bc99d1c3d7cadd feat(calendar): enforce agent context tiers in retrieval AP… Human minor ⚠ breaking 1 day ago
1 /**
2 * Unit tests for hub/bridge/index-timing.mjs (POST /api/v1/index per-step instrumentation).
3 *
4 * Why we test this in isolation rather than booting the bridge:
5 * - The bridge's index handler depends on Netlify Blobs, the canister export, sqlite-vec,
6 * and a live embedding provider. Spinning all of that up to assert a console.log line
7 * is a bad cost/benefit trade.
8 * - The timer is a pure module with an injected `logger` + `now` so we can deterministically
9 * verify the JSON shape, the step ordering, and the idempotent `finish` semantics that
10 * the index handler depends on. If any of these regress, the post-mortem signal we rely
11 * on for the timeout fix breaks silently — exactly the failure mode this PR exists to fix.
12 */
13
14 import { describe, it } from 'node:test';
15 import assert from 'node:assert/strict';
16
17 import { createIndexTimer } from '../hub/bridge/index-timing.mjs';
18
19 /**
20 * Capture console.log lines into an array via the logger injection point.
21 * @returns {{ logger: (line: string) => void, lines: string[] }}
22 */
23 function captureLogger() {
24 const lines = [];
25 return { logger: (line) => lines.push(line), lines };
26 }
27
28 /**
29 * Deterministic clock that advances by `delta` ms each call.
30 * @param {number} startMs
31 * @param {number[]} deltas
32 */
33 function fakeClock(startMs, deltas) {
34 let i = -1;
35 let cursor = startMs;
36 return () => {
37 i++;
38 if (i === 0) return cursor;
39 cursor += deltas[i - 1] ?? 0;
40 return cursor;
41 };
42 }
43
44 describe('createIndexTimer', () => {
45 it('emits a JSON line per step under the stable type knowtation_index_step', () => {
46 const cap = captureLogger();
47 const now = fakeClock(1_700_000_000_000, [10, 20, 30]);
48 const timer = createIndexTimer({ vaultId: 'v1', canisterUid: 'uid:1', logger: cap.logger, now });
49 timer.step('resolve_context');
50 timer.step('canister_export', { note_count: 7 });
51 assert.equal(cap.lines.length, 2);
52 const a = JSON.parse(cap.lines[0]);
53 const b = JSON.parse(cap.lines[1]);
54 assert.equal(a.type, 'knowtation_index_step');
55 assert.equal(a.step, 'resolve_context');
56 assert.equal(a.vault_id, 'v1');
57 assert.equal(a.canister_uid, 'uid:1');
58 assert.ok(typeof a.ts === 'string' && a.ts.endsWith('Z'));
59 assert.equal(typeof a.ms, 'number');
60 assert.equal(typeof a.total_ms, 'number');
61 assert.equal(b.note_count, 7, 'extra fields must merge into the line');
62 });
63
64 it('measures elapsed ms per step and cumulative total_ms', () => {
65 const cap = captureLogger();
66 // t0=0, step1 +250, step2 +750, finish +0
67 const now = fakeClock(0, [250, 750, 0]);
68 const timer = createIndexTimer({ logger: cap.logger, now });
69 timer.step('a');
70 timer.step('b');
71 const a = JSON.parse(cap.lines[0]);
72 const b = JSON.parse(cap.lines[1]);
73 assert.equal(a.ms, 250);
74 assert.equal(a.total_ms, 250);
75 assert.equal(b.ms, 750);
76 assert.equal(b.total_ms, 1000);
77 });
78
79 it('finish emits knowtation_index_done with step_count and merged extras', () => {
80 const cap = captureLogger();
81 const now = fakeClock(0, [10, 20, 5]);
82 const timer = createIndexTimer({ vaultId: 'vault-x', logger: cap.logger, now });
83 timer.step('a');
84 timer.step('b');
85 const total = timer.finish({ ok: true, chunks_indexed: 42 });
86 const last = JSON.parse(cap.lines.at(-1));
87 assert.equal(last.type, 'knowtation_index_done');
88 assert.equal(last.step_count, 2);
89 assert.equal(last.ok, true);
90 assert.equal(last.chunks_indexed, 42);
91 assert.equal(last.vault_id, 'vault-x');
92 assert.equal(typeof last.total_ms, 'number');
93 assert.equal(total, last.total_ms);
94 });
95
96 it('finish is idempotent: calling step() after finish() is a no-op (no extra log)', () => {
97 const cap = captureLogger();
98 const now = fakeClock(0, [10, 0, 0]);
99 const timer = createIndexTimer({ logger: cap.logger, now });
100 timer.step('a');
101 timer.finish({ ok: true });
102 timer.step('post_finish_should_be_noop');
103 timer.finish({ ok: false });
104 const types = cap.lines.map((l) => JSON.parse(l).type);
105 assert.deepEqual(types, ['knowtation_index_step', 'knowtation_index_done']);
106 });
107
108 it('rejects empty step names early so we never silently emit untyped log lines', () => {
109 const cap = captureLogger();
110 const timer = createIndexTimer({ logger: cap.logger });
111 assert.throws(() => timer.step(''), /non-empty/i);
112 assert.throws(() => timer.step(undefined), /non-empty/i);
113 assert.equal(cap.lines.length, 0);
114 });
115
116 it('default logger is console.log and default now is Date.now (smoke; do not over-assert)', () => {
117 const orig = console.log;
118 const lines = [];
119 console.log = (line) => lines.push(line);
120 try {
121 const timer = createIndexTimer();
122 timer.step('warmup', { warm: true });
123 const total = timer.finish({ ok: true });
124 assert.ok(total >= 0);
125 assert.equal(lines.length, 2);
126 const step = JSON.parse(lines[0]);
127 assert.equal(step.step, 'warmup');
128 assert.equal(step.warm, true);
129 } finally {
130 console.log = orig;
131 }
132 });
133
134 it('null vaultId / canisterUid still serialize as null (logs must remain greppable on early errors)', () => {
135 const cap = captureLogger();
136 const now = fakeClock(0, [1]);
137 const timer = createIndexTimer({ logger: cap.logger, now });
138 timer.step('resolve_context', { ok: false });
139 const a = JSON.parse(cap.lines[0]);
140 assert.equal(a.vault_id, null);
141 assert.equal(a.canister_uid, null);
142 assert.equal(a.ok, false);
143 });
144 });
File History 2 commits
sha256:65ccb454656ea5acdea0a10e559b78bcde1eb6ff753ecc2911bc99d1c3d7cadd feat(calendar): enforce agent context tiers in retrieval AP… Human minor ⚠ 1 day ago
sha256:9103f98c89257ed2b01c237cea895dabb3e85ea337dccb1161c175e4422355b6 docs: accept Calendar Events v0 spec with Phase 0 security … Human 1 day ago