// SPDX-License-Identifier: GPL-2.0-or-later // Copyright (C) 2026 Bryan Joshua Pedini /** * PLAN §12 core item 17: `audit`, `audit all`, `audit ` and `audit ` through the * compiled binary — header, exact rows and chronological order against the `operations` rows read * directly from SQLite, the default of 10, every row with `all` (also more than 10, and ties on * equal stored times in insertion order), counts larger than the row count, every unit, a real * time window and its boundary band, operation while the server runs (also under concurrent load * and across restarts), the read-only guarantee (byte-identical database), every usage-error class * (including the near misses of `all`), configuration-error precedence, log levels, an * unparseable stored time, and a population of 4000 rows produced by real authenticated requests. * * Rows only ever come from real authenticated GETs against FakeDocker. Only two scenarios write * to the database themselves (server stopped, test-owned connection): the unparseable-time test * and the equal-timestamps ordering test of `audit all`, which can only get identical stored * times that way. */ import fs from 'node:fs'; import { DatabaseSync } from 'node:sqlite'; import { test, expect, AUDIT_COLUMNS, EMPTY_AUDIT, LOG_LEVELS, USAGE_TEXT, assertDbInvariants, buildRawRequest, expectCliFailure, expectCliSuccess, expectContainersResponse, fileDigest, formatAuditOutput, levelRank, mapLimit, msToNanos, parseAuditOutput, parseLogs, parseTokenList, padTable, pollUntil, printsTokens, readOperations, rfc3339ToNanos, RFC3339NANO_UTC_RE, tokenId, visibleLevels, type AuditRow, type CliRunner, type HttpClient, type LogLevel, type ServerHandle, } from '../../harness'; import { AUDIT_ALL_EXTRA_ARGS, AUDIT_ALL_NEAR_MISSES, AUDIT_MAX_WINDOW, AUDIT_UNITS, auditArgsOutcome, chronological, expectAuditWindow, expectedAuditStdout, expectNoTokenFragments, stateDigest, } from '../../harness/personas'; const SECOND = AUDIT_UNITS.s; const nowNs = (skewMs = 0) => msToNanos(Date.now() + skewMs); /** One authenticated GET per token in `plan`, sequentially (Playwright request); all must be 200. */ async function sequential(http: HttpClient, server: ServerHandle, plan: string[]): Promise { for (const t of plan) expectContainersResponse(await http.get(server.url(), { token: t })); } /** * Real authenticated GETs pipelined over keep-alive connections (`perConn` requests each, * `concurrency` connections at a time) — a fast way to produce thousands of audit rows. */ async function pipelined(http: HttpClient, server: ServerHandle, plan: string[], { perConn = 50, concurrency = 8 } = {}): Promise { const chunks: string[][] = []; for (let i = 0; i < plan.length; i += perConn) chunks.push(plan.slice(i, i + perConn)); await mapLimit(chunks, concurrency, async (chunk, ci) => { const data = chunk.map((t, i) => buildRawRequest({ target: '/api/v1/containers', headers: [['Authorization', `Bearer ${t}`]], close: i === chunk.length - 1 })).join(''); const r = await http.raw({ host: server.connectHost, port: server.port, data, expectResponses: chunk.length, timeoutMs: 30_000 }); expect(r.responses.map((x) => x.status), `pipelined connection ${ci}: every request answered 200`).toEqual(chunk.map(() => 200)); }); } /** * `audit ...args` against `dbPath`: exit 0, empty stderr, strictly parseable stdout that equals * the oracle's selection over the stored rows byte for byte (windows: no stored row may lie in * the boundary band, so the expectation is exact). No writer may run concurrently. */ async function expectAudit(cli: CliRunner, dbPath: string, args: string[], label = `audit ${JSON.stringify(args)}`): Promise { const parsed = auditArgsOutcome(args); if (!parsed.ok) throw new Error(`${label}: not a valid audit argument list`); const t0 = nowNs(-1); const r = await cli.run(['audit', ...args], { env: { DB_PATH: dbPath } }); const t1 = nowNs(1); expectCliSuccess(r, { stderr: '' }); const rows = parseAuditOutput(r.stdout); const ops = readOperations(dbPath); const sel = parsed.selection; if ('windowNs' in sel) expect(expectAuditWindow(rows, ops, sel.windowNs, t0, t1, label), `${label}: no stored row near the window boundary`).toBe(0); else expect(r.stdout, `${label}: stdout equals the stored rows`).toBe(expectedAuditStdout(ops, sel)); return rows; } test.describe('audit selection forms', () => { test('fresh database: header only for every form; the database and the empty schema are created, as by the token commands', async ({ cli, ws }) => { const forms = [[], ['all'], ['1'], ['10'], ['9223372036854775807'], ['1s'], ['1m'], ['1h'], ['1d'], ['1w'], ['15250w']]; await mapLimit(forms, 5, async (args, i) => { const db = ws.path(`fresh-${i}.db`); expect(fs.existsSync(db)).toBe(false); const r = await cli.run(['audit', ...args], { env: { DB_PATH: db } }); expectCliSuccess(r, { stdout: EMPTY_AUDIT, stderr: '' }); expect(fs.existsSync(db), `audit ${args.join(' ')}: database created`).toBe(true); assertDbInvariants(db, { tokenCount: 0, operationCount: 0 }); }); // tokens but no operations yet: still only the header await cli.tokenNew('no requests yet'); for (const args of forms) expectCliSuccess(await cli.run(['audit', ...args]), { stdout: EMPTY_AUDIT, stderr: '' }); assertDbInvariants(ws.dbPath, { tokenCount: 1, operationCount: 0 }); }); test('default 10 and explicit counts with fewer than, exactly and more than 10 rows: exact rows and order from SQLite (server running)', async ({ cli, ws, startServer, http }) => { const [a, b, c] = [await cli.tokenNew('a'), await cli.tokenNew('b'), await cli.tokenNew('c')]; const server = await startServer(); const plan: string[] = []; const add = async (tokens: string[]) => { await sequential(http, server, tokens); plan.push(...tokens); expect(readOperations(ws.dbPath).map((o) => o.token), 'one row per request, in order').toEqual(plan); }; await test.step('3 rows (fewer than 10)', async () => { await add([a, b, c]); expect(await expectAudit(cli, ws.dbPath, [])).toHaveLength(3); for (const n of ['1', '2', '3', '4', '10']) await expectAudit(cli, ws.dbPath, [n]); }); await test.step('exactly 10 rows', async () => { await add([a, a, b, c, c, a, b]); const rows = await expectAudit(cli, ws.dbPath, []); expect(rows.map((r) => r.token)).toEqual(plan); for (const n of ['9', '10', '11']) await expectAudit(cli, ws.dbPath, [n]); }); await test.step('25 rows (more than 10)', async () => { await add([c, b, a, a, a, c, b, b, c, a, b, c, a, c, b]); const rows = await expectAudit(cli, ws.dbPath, []); expect(rows.map((r) => r.token), 'the latest 10, oldest first').toEqual(plan.slice(-10)); for (const n of ['1', '24', '25', '26', '1000', '010', '0000000000000000000000000000025', '9223372036854775807', '00009223372036854775807']) { await expectAudit(cli, ws.dbPath, [n]); } const all = await expectAudit(cli, ws.dbPath, ['1000']); expect(all.map((r) => r.token)).toEqual(plan); expect(all.every((r) => r.origin === '127.0.0.1' && r.operation === 'GET containers')).toBe(true); }); expect((await server.stop()).exitCode).toBe(0); assertDbInvariants(ws.dbPath, { tokenCount: 3, operationCount: 25 }); }); test('every unit s/m/h/d/w, leading zeros and the largest window per unit select every recent row', async ({ cli, ws, startServer, http }) => { const t = await cli.tokenNew('units'); const server = await startServer(); await sequential(http, server, [t, t, t, t, t, t]); const forms = ['120s', '3600s', '2m', '60m', '1h', '01h', '0001d', '1d', '1w', '00001w']; for (const u of Object.keys(AUDIT_MAX_WINDOW) as Array) forms.push(`${AUDIT_MAX_WINDOW[u]}${u}`); for (const f of forms) expect(await expectAudit(cli, ws.dbPath, [f]), f).toHaveLength(6); expect((await server.stop()).exitCode).toBe(0); for (const f of ['1h', '15250w']) expect(await expectAudit(cli, ws.dbPath, [f]), `${f} after the server stopped`).toHaveLength(6); }); test('real time window: after a 2 s gap `audit 2s` prints exactly the later rows; every window is a chronological suffix with no row on the wrong side of its boundary band', async ({ cli, ws, startServer, http }) => { const [early, late] = [await cli.tokenNew('early'), await cli.tokenNew('late')]; const server = await startServer(); await sequential(http, server, [early, early, early, early]); const lastEarly = rfc3339ToNanos(chronological(readOperations(ws.dbPath)).at(-1)!.time); // poll the clock until the early rows are more than 2 s old (no fixed sleep) await pollUntil('the early rows to be older than 2 s', () => (nowNs(-30) > lastEarly + 2n * SECOND ? true : undefined), { timeoutMs: 10_000, intervalMs: 10 }); await sequential(http, server, [late, late, late]); const t0 = nowNs(-1); const r = await cli.run(['audit', '2s']); const t1 = nowNs(1); expectCliSuccess(r, { stderr: '' }); const ops = readOperations(ws.dbPath); const rows = parseAuditOutput(r.stdout); expect(expectAuditWindow(rows, ops, 2n * SECOND, t0, t1, 'audit 2s'), 'no stored row inside the boundary band').toBe(0); expect(r.stdout, 'exactly the rows written after the gap').toBe(formatAuditOutput(ops.slice(4))); expect(rows.map((x) => x.token)).toEqual([late, late, late]); // boundary sanity for a range of windows: each output is a chronological suffix, every row at or // after now - window is printed and none before; the selections are nested let previous = -1; for (const w of ['1s', '2s', '3s', '5s', '30s', '1m', '1h']) { const s0 = nowNs(-1); const x = await cli.run(['audit', w]); const s1 = nowNs(1); expectCliSuccess(x, { stderr: '' }); const xs = parseAuditOutput(x.stdout); const sel = auditArgsOutcome([w]); if (!sel.ok || !('windowNs' in sel.selection)) throw new Error('window expected'); expectAuditWindow(xs, ops, sel.selection.windowNs, s0, s1, `audit ${w}`); expect(xs.length >= previous, `audit ${w} includes the rows of the smaller windows`).toBe(true); previous = xs.length; } expect(previous, 'audit 1h: every row').toBe(7); expect((await server.stop()).exitCode).toBe(0); }); }); test.describe('audit all', () => { test('empty database: `audit all` prints exactly the padded header, exit 0, empty stderr (fresh file and tokens without requests)', async ({ cli, ws }) => { expect(EMPTY_AUDIT, 'the header-only table').toBe(padTable([AUDIT_COLUMNS])); expect(EMPTY_AUDIT).toBe('TIME TOKEN ORIGIN OPERATION\n'); const r = await cli.run(['audit', 'all']); expectCliSuccess(r, { stdout: EMPTY_AUDIT, stderr: '' }); assertDbInvariants(ws.dbPath, { tokenCount: 0, operationCount: 0 }); await cli.tokenNew('never used'); await cli.tokenDelete(await cli.tokenNew('deleted, never used')); expect(await cli.audit('all')).toEqual([]); expectCliSuccess(await cli.run(['audit', 'all']), { stdout: EMPTY_AUDIT, stderr: '' }); assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 0 }); }); test('every row, oldest first, as the exact padded table with 1, exactly 10, 11 and 25 rows (more than the default 10); tokens printed are registered secrets', async ({ cli, ws, startServer, http, secrets }) => { expect(printsTokens(['audit', 'all']), 'audit all stdout is scanned for tokens').toBe(true); const [a, b, c] = [await cli.tokenNew('all a'), await cli.tokenNew('all b'), await cli.tokenNew('all c')]; const server = await startServer(); const plan: string[] = []; for (const batch of [[a], [b, c, a, a, b, c, c, b, a], [c], [a, b, c, a, b, c, a, b, c, a, b, c, a, b]]) { await sequential(http, server, batch); plan.push(...batch); await test.step(`${plan.length} rows`, async () => { const ops = readOperations(ws.dbPath); expect(ops.map((o) => o.token), 'one row per request, in order').toEqual(plan); const r = await cli.run(['audit', 'all']); expectCliSuccess(r, { stderr: '' }); // exact stdout: the padded table of every stored row, oldest first const expected = padTable([[...AUDIT_COLUMNS], ...chronological(ops).map((o) => [o.time, o.token, o.origin, o.operation])]); expect(r.stdout, 'stdout is the padded table of every stored row').toBe(expected); expect(r.stdout, 'the oracle agrees').toBe(expectedAuditStdout(ops, { all: true })); const rows = parseAuditOutput(r.stdout); expect(rows.map((x) => x.token), 'every row, oldest first').toEqual(plan); expect(rows.map((x) => x.time), 'TIME exactly as stored').toEqual(ops.map((o) => o.time)); const times = rows.map((x) => rfc3339ToNanos(x.time)); expect(times.every((t, k) => k === 0 || times[k - 1] <= t), 'chronological').toBe(true); // the same bytes as a count that covers every row; the default still stops at 10 expectCliSuccess(await cli.run(['audit', String(plan.length)]), { stdout: r.stdout, stderr: '' }); expect((await cli.audit()).map((x) => x.token), 'plain audit: the latest 10').toEqual(plan.slice(-10)); }); } expect(plan).toHaveLength(25); for (const t of [a, b, c]) expect(secrets.has(t)).toBe(true); expect((await server.stop()).exitCode).toBe(0); expect(formatAuditOutput(await cli.audit('all')), 'with the server stopped').toBe(expectedAuditStdout(readOperations(ws.dbPath), { all: true })); assertDbInvariants(ws.dbPath, { tokenCount: 3, operationCount: 25 }); }); test('equal stored times are printed in insertion order (rowid), after the earlier times — also for rows inserted later with an earlier time', async ({ cli, ws, startServer, http }) => { const [a, b] = [await cli.tokenNew('ties a'), await cli.tokenNew('ties b')]; const server = await startServer(); await sequential(http, server, [a, a, b, b, a, b]); // no server may use the database while the test writes to it expect((await server.stop()).exitCode).toBe(0); const ops = readOperations(ws.dbPath); expect(ops).toHaveLength(6); const [r0, r1, r2, r3, r4, r5] = ops; // Test-owned write (the only way to get identical stored times): r1, r4, r5 share the latest // time, r3 the earliest one (tie with r0, inserted later). Every new value is an existing, // valid stored time after the tokens' created_at, so the database invariants still hold. const assign: Array<[number, string]> = [ [r1.rowid, r5.time], [r3.rowid, r0.time], [r4.rowid, r5.time], ]; const db = new DatabaseSync(ws.dbPath, { timeout: 5000 }); try { for (const [rowid, time] of assign) expect(Number(db.prepare('UPDATE operations SET time = ? WHERE rowid = ?').run(time, rowid).changes)).toBe(1); } finally { db.close(); } assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 6 }); const tied = readOperations(ws.dbPath); const byRowid = new Map(tied.map((o) => [o.rowid, o])); const order = [r0, r3, r2, r1, r4, r5].map((o) => byRowid.get(o.rowid)!); expect(chronological(tied).map((o) => o.rowid), 'the oracle orders by time, then rowid').toEqual(order.map((o) => o.rowid)); const r = await cli.run(['audit', 'all']); expectCliSuccess(r, { stderr: '' }); expect(r.stdout, 'time, then insertion order').toBe(formatAuditOutput(order)); expect(r.stdout).toBe(expectedAuditStdout(tied, { all: true })); expect(parseAuditOutput(r.stdout).map((x) => x.token)).toEqual([a, b, b, a, a, b]); // the other forms agree with the same order expectCliSuccess(await cli.run(['audit', '100']), { stdout: r.stdout, stderr: '' }); expectCliSuccess(await cli.run(['audit', '3']), { stdout: formatAuditOutput(order.slice(-3)), stderr: '' }); // stable across invocations for (let i = 0; i < 3; i++) expectCliSuccess(await cli.run(['audit', 'all']), { stdout: r.stdout, stderr: '' }); }); test('near misses of `all` (case, digits, blanks, options, extra arguments): exact usage error, nothing echoed, no database created, an existing one untouched', async ({ cli, ws }) => { const cases: Array<[string[], string]> = [ ...[...new Set(['ALL', 'All', 'all1', '1all', ' all', 'alls', '--all', ...AUDIT_ALL_NEAR_MISSES.map(([v]) => v)])].map((v): [string[], string] => [[v], INVALID]), ...AUDIT_ALL_EXTRA_ARGS.map((args): [string[], string] => [[...args], TOO_MANY]), ]; expect(cases.map(([a]) => JSON.stringify(a)), 'the required near misses are covered').toEqual(expect.arrayContaining(['["ALL"]', '["All"]', '["all1"]', '["1all"]', '[" all"]', '["alls"]', '["--all"]', '["all","x"]'])); for (const [args, msg] of cases) expect(auditArgsOutcome(args), JSON.stringify(args)).toEqual({ ok: false, message: msg }); const run = () => mapLimit(cases, 8, async ([args, msg]) => { const r = await cli.run(['audit', ...args]); expectCliFailure(r, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); expect(r.stderr, `${JSON.stringify(args)}: exact stderr, the argument is never echoed`).toBe(`dpsapi: usage error: ${msg}\n${USAGE_TEXT}`); }); await run(); expect(fs.readdirSync(ws.dir), 'no database created').toEqual([]); await cli.tokenNew('existing'); const file = fileDigest(ws.dbPath); const state = stateDigest(ws.dbPath); await run(); expect(fileDigest(ws.dbPath)).toBe(file); expect(stateDigest(ws.dbPath)).toBe(state); }); }); test.describe('audit against live and changing state', () => { test('output equals the operations rows in SQLite (exact time, full token, origin, operation, order) across concurrent writers, token deletion and server restarts', async ({ cli, ws, startServer, http }) => { const tokens = await Promise.all(['ci', 'ops', 'dash', 'backup'].map((d) => cli.tokenNew(d))); const server = await startServer(); // concurrent writers: interleaved times, variable-length fractions (trailing zeros dropped) await mapLimit(Array.from({ length: 40 }, (_, i) => tokens[i % 4]), 8, async (t, i) => { expectContainersResponse(i % 5 === 0 ? await http.curl({ url: server.url(), token: t }) : await http.get(server.url(), { token: t })); }); const check = async (label: string, expected: number) => { const all = await expectAudit(cli, ws.dbPath, ['100000'], `${label}: audit 100000`); expect(all, label).toHaveLength(expected); expect(await expectAudit(cli, ws.dbPath, ['all'], `${label}: audit all`), `${label}: audit all = audit 100000`).toEqual(all); await expectAudit(cli, ws.dbPath, [], `${label}: audit`); await expectAudit(cli, ws.dbPath, ['7'], `${label}: audit 7`); await expectAudit(cli, ws.dbPath, ['1h'], `${label}: audit 1h`); // every printed token is a full token known to `token list all` (active or not) const listed = new Set((await cli.tokenListAll()).map((r) => r.token)); expect(all.every((r) => listed.has(r.token)), `${label}: tokens correlate with token list all`).toBe(true); return all; }; const first = await check('after 40 concurrent requests', 40); // lexical and chronological order differ whenever a fraction lost trailing zeros: informative only const lexicalInversions = first.filter((r, i) => i > 0 && first[i - 1].time > r.time).length; test.info().annotations.push({ type: 'audit ordering', description: `${lexicalInversions} adjacent row pair(s) whose TIME text sorts differently from the instant` }); await test.step('deleted tokens keep their rows, printed with the full token', async () => { await cli.tokenDelete(tokens[1]); await cli.tokenDelete(tokens[2]); const all = await check('after deleting two tokens', 40); expect(all.filter((r) => r.token === tokens[1])).toHaveLength(10); expect(all.filter((r) => r.token === tokens[2])).toHaveLength(10); }); await test.step('across a restart', async () => { await server.restart(); await check('after a restart', 40); await sequential(http, server, [tokens[0], tokens[3], tokens[0]]); const all = await check('after requests on the new generation', 43); expect(all.slice(0, 40)).toEqual(first); expect(all.slice(40).map((r) => r.token)).toEqual([tokens[0], tokens[3], tokens[0]]); }); expect((await server.stop()).exitCode).toBe(0); await check('with the server stopped', 43); assertDbInvariants(ws.dbPath, { tokenCount: 4, operationCount: 43 }); }); test('while the server is under concurrent load: every output is a complete table and a consistent snapshot of the history', async ({ cli, ws, startServer, http }) => { test.setTimeout(90_000); const tokens = await Promise.all([1, 2, 3, 4].map((i) => cli.tokenNew(`load ${i}`))); const server = await startServer(); const PER_TOKEN = 60; let started = 0; let completed = 0; let failed = false; const writer = async (t: string) => { try { for (let i = 0; i < PER_TOKEN; i++) { started++; expectContainersResponse(await http.get(server.url(), { token: t })); completed++; } } catch (e) { failed = true; // stop the reader too: a failed writer must not turn into a hang throw e; } }; const forms = [['1000000'], [], ['all'], ['1h'], ['01d'], ['5']]; const snaps: Array<{ args: string[]; stdout: string; before: number; after: number }> = []; const reader = async () => { for (let k = 0; !failed && completed < tokens.length * PER_TOKEN; k++) { const args = forms[k % forms.length]; const before = completed; const r = await cli.run(['audit', ...args]); expectCliSuccess(r, { stderr: '' }); snaps.push({ args, stdout: r.stdout, before, after: started }); } }; await Promise.all([...tokens.map(writer), reader()]); expect(snaps.length, 'audit ran repeatedly during the load').toBeGreaterThan(10); const final = chronological(readOperations(ws.dbPath)); expect(final).toHaveLength(tokens.length * PER_TOKEN); // compared by cells: the padding of a line depends on the widest cells of that invocation const cells = (r: { time: string; token: string; origin: string; operation: string }) => [r.time, r.token, r.origin, r.operation].join('\t'); const finalLines = final.map(cells); const isSubsequence = (lines: string[]) => { let j = 0; for (const l of lines) { while (j < finalLines.length && finalLines[j] !== l) j++; if (j++ >= finalLines.length) return false; } return true; }; for (const [i, s] of snaps.entries()) { const label = `snapshot ${i} (audit ${s.args.join(' ')}, ${s.before} rows committed before it started, ${s.after} requests started before it ended)`; const rows = parseAuditOutput(s.stdout); // strict: a torn line or header fails here const times = rows.map((r) => rfc3339ToNanos(r.time)); expect(times.every((t, k) => k === 0 || times[k - 1] <= t), `${label}: chronological`).toBe(true); expect(isSubsequence(rows.map(cells)), `${label}: every row is a stored row, in the final relative order`).toBe(true); expect(s.stdout, `${label}: padded table of its own rows`).toBe(formatAuditOutput(rows)); const limit = s.args[0] === '5' ? 5 : s.args.length === 0 ? 10 : Infinity; expect(rows.length, `${label}: lower bound`).toBeGreaterThanOrEqual(Math.min(limit, s.before)); expect(rows.length, `${label}: upper bound`).toBeLessThanOrEqual(Math.min(limit, s.after)); } await expectAudit(cli, ws.dbPath, ['1000000'], 'after the load'); expect((await server.stop()).exitCode).toBe(0); assertDbInvariants(ws.dbPath, { tokenCount: 4, operationCount: tokens.length * PER_TOKEN }); }); test('read-only: database file and WAL byte-identical, logical state unchanged and no audit row created, for every form at every log level', async ({ cli, ws, startServer, http }) => { const t = await cli.tokenNew('read-only'); const dead = await cli.tokenNew('deleted'); const server = await startServer(); await sequential(http, server, [t, dead, t, dead, t]); await cli.tokenDelete(dead); const wal = `${ws.dbPath}-wal`; const before = { db: fileDigest(ws.dbPath), wal: fileDigest(wal), state: stateDigest(ws.dbPath), ops: readOperations(ws.dbPath) }; expect(before.wal, 'the running server keeps a WAL file').toBeDefined(); for (const level of LOG_LEVELS) { for (const args of [[], ['all'], ['3'], ['1000'], ['1h'], ['1w']]) { const r = await cli.run(['audit', ...args], { env: { LOG_LEVEL: level } }); expectCliSuccess(r); const label = `audit ${args.join(' ')} at ${level}`; expect(fileDigest(ws.dbPath), `${label}: database file bytes`).toBe(before.db); expect(fileDigest(wal), `${label}: WAL bytes`).toBe(before.wal); expect(stateDigest(ws.dbPath), `${label}: logical state`).toBe(before.state); } } expect(readOperations(ws.dbPath), 'running audit created no audit row').toEqual(before.ops); expect(server.logs().requests(), 'audit never talks to the server').toHaveLength(5); expect((await server.stop()).exitCode).toBe(0); // closed database (no server): still nothing written const closed = { db: fileDigest(ws.dbPath), state: stateDigest(ws.dbPath) }; for (const args of [[], ['all'], ['2'], ['1d']]) { expectCliSuccess(await cli.run(['audit', ...args]), { stderr: '' }); expect(fileDigest(ws.dbPath), `audit ${args.join(' ')} on a closed database: file bytes`).toBe(closed.db); expect(stateDigest(ws.dbPath)).toBe(closed.state); } assertDbInvariants(ws.dbPath, { tokenCount: 2, operationCount: 5 }); }); }); const INVALID = 'invalid audit argument'; const TOO_MANY = 'audit takes at most one argument'; const invalid = (...values: string[]): Array<[string[], string]> => values.map((v) => [[v], INVALID]); /** Every class of invalid `audit` argument (README "audit", PLAN §3). */ const USAGE_ERRORS: Array<[string[], string]> = [ // more than one argument [['10', 'h'], TOO_MANY], [['1', '2'], TOO_MANY], [['10', 'hours'], TOO_MANY], [['', ''], TOO_MANY], [['1h', '--json'], TOO_MANY], [['1', '2', '3'], TOO_MANY], // zero in any form ...invalid('0', '000', '0s', '0m', '00h', '0d', '0000w'), // signs ...invalid('-5', '+5', '-0', '-1h', '+1h', '−5'), // whitespace ...invalid(' 5', '5 ', '5\n', '\t5', '5 h', '1 0', ' ', '5 ', ' 5', '5h\r'), // empty argument ...invalid(''), // uppercase and unknown units ...invalid('5S', '5M', '5H', '5D', '5W', '5y', '5ms', '5us', '5µs', '5ns', '5sec', '30min', '1hour', '5x', '5ss', '5hh', '5ѕ', '5s'), // unit without digits ...invalid('s', 'm', 'h', 'd', 'w', 'hh'), // other number syntaxes ...invalid('1.5', '1.5h', '1e3', '0x10', '0b1', '1_000', '1,000', '½', '10', '٣', 'ten', 'NaN', 'Infinity', '1h30m', 's5', '5d5'), // count overflowing int64, window overflowing time.Duration ...invalid('9223372036854775808', '18446744073709551616', '99999999999999999999999999', '9223372037s', '153722868m', '2562048h', '106752d', '15251w', '99999999999999999999w'), // looks like an option ...invalid('--help', '-n', '--tail=10'), // near misses of `all` (exact, lowercase only) and `all` with extra arguments ...invalid(...new Set(['ALL', 'All', 'all1', '1all', ' all', 'alls', '--all', ...AUDIT_ALL_NEAR_MISSES.map(([v]) => v)])), ...AUDIT_ALL_EXTRA_ARGS.map((args): [string[], string] => [[...args], TOO_MANY]), ]; test.describe('audit usage and configuration errors', () => { test(`${USAGE_ERRORS.length} invalid argument lists → exit 2, exact error line + usage text, nothing echoed, no database created / existing one untouched`, async ({ cli, ws, startServer, http }) => { // the oracle agrees with the table (and the table with the README) for (const [args, msg] of USAGE_ERRORS) expect(auditArgsOutcome(args), JSON.stringify(args)).toEqual({ ok: false, message: msg }); const run = async (dbPath: string) => mapLimit(USAGE_ERRORS, 8, async ([args, msg]) => { const r = await cli.run(['audit', ...args], { env: { DB_PATH: dbPath } }); expectCliFailure(r, { exitCode: 2, message: `usage error: ${msg}`, usage: true }); // exact stderr: the argument is never echoed expect(r.stderr, JSON.stringify(args)).toBe(`dpsapi: usage error: ${msg}\n${USAGE_TEXT}`); }); await test.step('fresh workspace: the database is never created', async () => { const never = ws.path('never.db'); await run(never); expect(fs.readdirSync(ws.dir), 'nothing written to the workspace').toEqual([]); }); await test.step('existing database with audit rows: byte-identical afterwards', async () => { const t = await cli.tokenNew('existing'); const server = await startServer(); await sequential(http, server, [t, t, t]); expect((await server.stop()).exitCode).toBe(0); const file = fileDigest(ws.dbPath); const state = stateDigest(ws.dbPath); await run(ws.dbPath); expect(fileDigest(ws.dbPath)).toBe(file); expect(stateDigest(ws.dbPath)).toBe(state); expect(await expectAudit(cli, ws.dbPath, [])).toHaveLength(3); }); }); test('the largest accepted count and windows are valid (exit 0)', async ({ cli, ws }) => { const edges = ['9223372036854775807', '00009223372036854775807', '9223372036s', '153722867m', '2562047h', '106751d', '15250w', '1s', '01h', '010', '1']; for (const e of edges) expect(auditArgsOutcome([e]).ok, e).toBe(true); await mapLimit(edges, 4, async (e) => expectCliSuccess(await cli.run(['audit', e]), { stdout: EMPTY_AUDIT, stderr: '' })); assertDbInvariants(ws.dbPath, { tokenCount: 0, operationCount: 0 }); }); test('configuration errors take precedence over audit usage errors (no usage text, no database)', async ({ cli, ws }) => { const cases: Array<[Record, string[], string]> = [ [{ DB_PATH: undefined }, ['0'], 'configuration error: DB_PATH is required'], [{ DB_PATH: '' }, ['1', 'h'], 'configuration error: DB_PATH must not be empty'], [{ HTTP_ADDR: 'localhost' }, ['-1'], 'configuration error: invalid HTTP_ADDR "localhost": must be an IPv4 or IPv6 address'], [{ HTTP_PORT: '0' }, ['1H'], 'configuration error: invalid HTTP_PORT "0": must be an integer between 1 and 65535'], [{ LOG_LEVEL: 'verbose' }, ['10', 'hours'], 'configuration error: invalid LOG_LEVEL "verbose": must be one of ERROR, WARN, INFO, DEBUG, TRACE'], // a valid audit invocation is rejected the same way: CLI mode validates every variable [{ HTTP_PORT: '70000' }, [], 'configuration error: invalid HTTP_PORT "70000": must be an integer between 1 and 65535'], [{ LOG_LEVEL: '' }, ['1h'], 'configuration error: LOG_LEVEL must not be empty'], ]; for (const [env, args, message] of cases) { const r = await cli.run(['audit', ...args], { env }); expectCliFailure(r, { exitCode: 2, message, usage: false }); } expect(fs.existsSync(ws.dbPath)).toBe(false); expect(fs.readdirSync(ws.dir)).toEqual([]); }); }); test('log levels: stdout byte-identical at every level, stderr carries exactly the records the level allows, never a token (only token_id)', async ({ cli, ws, startServer, http, secrets }) => { const a = await cli.tokenNew('log a'); const b = await cli.tokenNew('log b'); const server = await startServer(); await sequential(http, server, [a, b, a, b, a, a]); expect((await server.stop()).exitCode).toBe(0); await cli.tokenDelete(b); const ops = readOperations(ws.dbPath); const FUNCS = ['app.execute', 'app.runAuditCommand', 'OpenDatabase', 'InitializeSchema', 'app.auditList', 'AuditStore.ListOperations']; const forms: Array<{ args: string[]; dispatch: Record; rows: number }> = [ { args: [], dispatch: { command: 'audit', limit: '10' }, rows: 6 }, { args: ['3'], dispatch: { command: 'audit', limit: '3' }, rows: 3 }, { args: ['all'], dispatch: { command: 'audit', all: 'true' }, rows: 6 }, { args: ['2h'], dispatch: { command: 'audit', window: '2h0m0s' }, rows: 6 }, { args: ['0090m'], dispatch: { command: 'audit', window: '1h30m0s' }, rows: 6 }, ]; for (const f of forms) { const baseline = await cli.run(['audit', ...f.args]); expectCliSuccess(baseline, { stderr: '' }); expect(parseAuditOutput(baseline.stdout)).toHaveLength(f.rows); expect(baseline.stdout.includes(a) && baseline.stdout.includes(b), 'stdout carries the full tokens').toBe(true); for (const level of LOG_LEVELS) { await test.step(`audit ${f.args.join(' ')} at ${level}`, async () => { const t0 = nowNs(-1); const r = await cli.run(['audit', ...f.args], { env: { LOG_LEVEL: level } }); const t1 = nowNs(1); expectCliSuccess(r); expect(r.stdout, 'stdout identical at every level').toBe(baseline.stdout); // no token, nor any 12-character fragment of one, in stderr — although stdout has them expect(r.stderr.includes(a) || r.stderr.includes(b)).toBe(false); expectNoTokenFragments(r.stderr, secrets, `stderr at ${level}`); const logs = parseLogs(r.stderr); expect(logs.unparsed, 'stderr consists of slog records only').toEqual([]); const allowed = visibleLevels(level as LogLevel); expect(logs.records.filter((x) => !allowed.includes(x.level as LogLevel)).map((x) => x.raw)).toEqual([]); if (levelRank(level) >= levelRank('INFO')) expect(r.stderr, 'successful CLI commands are silent at INFO and above').toBe(''); if (levelRank(level) <= levelRank('DEBUG')) { expect(logs.find({ msg: 'configuration resolved' })!.attrs.log_level).toBe(level); expect(logs.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' }); expect(logs.filter({ msg: 'cli dispatch' }).map((x) => x.attrs)).toEqual([f.dispatch]); expect(logs.filter({ msg: 'audit rows listed' }).map((x) => x.attrs)).toEqual([{ rows: String(f.rows) }]); expect(logs.filter({ msg: 'cli command finished' }).map((x) => x.attrs)).toEqual([{ command: 'audit', ok: 'true' }]); for (const m of ['database schema initialized', 'database opened', 'database closed']) expect(logs.count({ level: 'DEBUG', msg: m }), m).toBe(1); const resolved = logs.filter({ msg: 'audit window resolved' }); if ('window' in f.dispatch) { expect(resolved).toHaveLength(1); const since = resolved[0].attrs.since; expect(since).toMatch(RFC3339NANO_UTC_RE); const w = auditArgsOutcome(f.args); const windowNs = w.ok && 'windowNs' in w.selection ? w.selection.windowNs : 0n; expect(rfc3339ToNanos(since) >= t0 - windowNs && rfc3339ToNanos(since) <= t1 - windowNs, `since=${since} is now - window`).toBe(true); } else expect(resolved, 'no window resolved for a count').toEqual([]); } else expect(logs.count({ level: 'DEBUG' })).toBe(0); if (level === 'TRACE') { for (const fn of FUNCS) { expect(logs.count({ msg: 'function entry', attrs: { func: fn } }), `entry ${fn}`).toBe(1); expect(logs.count({ msg: 'function exit', attrs: { func: fn } }), `exit ${fn}`).toBe(1); } // one `row read` per stored row (also outside the selection), token redacted to token_id const reads = logs.filter({ level: 'TRACE', msg: 'row read', attrs: { table: 'operations' } }); expect(reads.map((x) => x.attrs)).toEqual(ops.map((o) => ({ table: 'operations', rowid: String(o.rowid), token_id: tokenId(o.token), origin: o.origin, operation: o.operation, time: o.time }))); expect(logs.records.some((x) => 'token' in x.attrs), 'no record has a token attribute').toBe(false); } else expect(logs.count({ level: 'TRACE' })).toBe(0); }); } } }); test('an unparseable stored time fails every form with exit 1 and nothing on stdout; restoring the row restores the output', async ({ cli, ws, startServer, http, secrets }) => { const t = await cli.tokenNew('corrupt'); const server = await startServer(); await sequential(http, server, [t, t, t]); // no server may use the database while the test writes to it expect((await server.stop()).exitCode).toBe(0); const ops = readOperations(ws.dbPath); const good = formatAuditOutput(ops); const victim = ops[1]; // Test-owned write: the only scenario that writes to the application database. It replaces one // row's time and finally restores it; nothing else is touched. const setTime = (value: string) => { const db = new DatabaseSync(ws.dbPath, { timeout: 5000 }); try { const res = db.prepare('UPDATE operations SET time = ? WHERE rowid = ?').run(value, victim.rowid); expect(Number(res.changes)).toBe(1); } finally { db.close(); } }; const goParse = (v: string) => `read operation row: parse stored timestamp: parsing time ${JSON.stringify(v)} as "2006-01-02T15:04:05.999999999Z07:00": cannot parse ${JSON.stringify(v)} as "2006"`; const corrupt: Array<[string, string | RegExp]> = [ ['not-a-time', goParse('not-a-time')], ['', goParse('')], ['2026-13-01T00:00:00Z', /^read operation row: parse stored timestamp: parsing time "2026-13-01T00:00:00Z": month out of range$/], ['2026-10-05 22:00:00Z', /^read operation row: parse stored timestamp: parsing time "2026-10-05 22:00:00Z" as "2006-01-02T15:04:05\.999999999Z07:00": cannot parse /], ['1759700000', /^read operation row: parse stored timestamp: parsing time "1759700000" as "2006-01-02T15:04:05\.999999999Z07:00": cannot parse /], ]; for (const [value, message] of corrupt) { await test.step(`time = ${JSON.stringify(value)}`, async () => { setTime(value); // The harness invariant check flags the deliberately corrupt row — asserted here explicitly // (the check itself stays enabled everywhere else). expect(() => assertDbInvariants(ws.dbPath), 'assertDbInvariants flags the corrupt row').toThrow(/database invariants/); const state = stateDigest(ws.dbPath); for (const args of [[], ['all'], ['1'], ['1000'], ['1w'], ['15250w']]) { const r = await cli.run(['audit', ...args]); expectCliFailure(r, { exitCode: 1, message, usage: false }); expect(r.stdout, 'no partial output').toBe(''); } const trace = await cli.run(['audit'], { env: { LOG_LEVEL: 'TRACE' } }); expectCliFailure(trace, { exitCode: 1, message, usage: false, exactStderr: false }); expect(parseLogs(trace.stderr).unparsed.map((u) => u.text), 'only the final error line is not a log record').toHaveLength(1); secrets.assertNoSecretsIn(trace.stderr, 'TRACE stderr of the failing audit'); expect(stateDigest(ws.dbPath), 'the failing audit changed nothing').toBe(state); // the token table is unaffected expect(parseTokenList((await cli.run(['token', 'list'])).stdout).map((r) => r.token)).toEqual([t]); }); } setTime(victim.time); expectCliSuccess(await cli.run(['audit']), { stdout: good, stderr: '' }); assertDbInvariants(ws.dbPath, { tokenCount: 1, operationCount: 3 }); expect(readOperations(ws.dbPath)).toEqual(ops); }); test('population: 4000 audit rows from real authenticated requests over 40 tokens (pipelined keep-alive connections) — every form equals SQLite', async ({ cli, ws, startServer, http, rng, secrets }) => { test.setTimeout(120_000); const tokens = await mapLimit(Array.from({ length: 40 }, (_, i) => `population ${i}`), 16, (d) => cli.tokenNew(d)); const server = await startServer({ logLevel: 'ERROR' }); const N = 4000; const plan = Array.from({ length: N }, () => rng.pick(tokens)); const t0 = performance.now(); await pipelined(http, server, plan, { perConn: 50, concurrency: 10 }); const requestMs = performance.now() - t0; for (const victim of tokens.slice(0, 8)) await cli.tokenDelete(victim); const ops = readOperations(ws.dbPath); expect(ops).toHaveLength(N); const perToken = new Map(); for (const t of plan) perToken.set(t, (perToken.get(t) ?? 0) + 1); for (const [t, n] of perToken) expect(ops.filter((o) => o.token === t).length, `rows of ${tokenId(t)}`).toBe(n); const timings: Record = {}; for (const args of [[], ['all'], ['1'], ['10'], ['3999'], ['4000'], ['4001'], ['100000'], ['0100'], ['1h'], ['1d'], ['1w']]) { const s = performance.now(); const rows = await expectAudit(cli, ws.dbPath, args); timings[args.join(' ') || '(none)'] = Math.round(performance.now() - s); const sel = auditArgsOutcome(args); if (sel.ok && 'limit' in sel.selection) expect(rows).toHaveLength(Math.min(N, Number(sel.selection.limit))); else expect(rows).toHaveLength(N); } expect(Math.max(...Object.values(timings)), 'audit over 4000 rows stays fast').toBeLessThan(5000); // TRACE: one `row read` per row, identical stdout, no token in 4000+ log lines const full = await cli.run(['audit', '100000']); expectCliSuccess(await cli.run(['audit', 'all']), { stdout: full.stdout, stderr: '' }); const traced = await cli.run(['audit', 'all'], { env: { LOG_LEVEL: 'TRACE' } }); expectCliSuccess(traced); expect(traced.stdout).toBe(full.stdout); const logs = parseLogs(traced.stderr); expect(logs.count({ msg: 'row read', attrs: { table: 'operations' } })).toBe(N); secrets.assertNoSecretsIn(traced.stderr, 'TRACE stderr'); // the server serves on: the latest row printed is the next request expectContainersResponse(await http.get(server.url(), { token: tokens[39] })); const last = await expectAudit(cli, ws.dbPath, ['1']); expect(last.map((r) => r.token)).toEqual([tokens[39]]); expect((await server.stop()).exitCode).toBe(0); assertDbInvariants(ws.dbPath, { tokenCount: 40, operationCount: N + 1 }); test.info().annotations.push({ type: 'audit population', description: JSON.stringify({ rows: N, requestMs: Math.round(requestMs), auditMs: timings }) }); });