bryanpedini
0a6023e942
Entry point and dispatch, token list [all] / new / delete, audit [all | n | n<unit>] with padded table output, help, usage and exit codes; unit and e2e tests for commands, configuration precedence, logging and token lifecycle.
734 lines
42 KiB
TypeScript
734 lines
42 KiB
TypeScript
// SPDX-License-Identifier: GPL-2.0-or-later
|
||
// Copyright (C) 2026 Bryan Joshua Pedini
|
||
|
||
/**
|
||
* PLAN §12 core item 17: `audit`, `audit all`, `audit <n>` and `audit <n><unit>` 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<void> {
|
||
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<void> {
|
||
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<AuditRow[]> {
|
||
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<keyof typeof AUDIT_MAX_WINDOW>) 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ѕ', '5ｓ'),
|
||
// 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', '½', '１０', '٣', '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 | undefined>, 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<string, string>; 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<string, number>();
|
||
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<string, number> = {};
|
||
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 }) });
|
||
});
|