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.
292 lines
14 KiB
TypeScript
292 lines
14 KiB
TypeScript
// SPDX-License-Identifier: GPL-2.0-or-later
|
|
// Copyright (C) 2026 Bryan Joshua Pedini
|
|
|
|
/**
|
|
* PLAN §12 core items 2, 3, 14: start with explicit HTTP_ADDR/HTTP_PORT at every LOG_LEVEL and
|
|
* verify which records must and must not be emitted, for server and CLI mode.
|
|
*/
|
|
import {
|
|
test,
|
|
expect,
|
|
LOG_LEVELS,
|
|
LOG_TIME_RE,
|
|
USAGE_TEXT,
|
|
levelRank,
|
|
parseLogs,
|
|
tokenId,
|
|
visibleLevels,
|
|
expectContainersResponse,
|
|
expectErrorResponse,
|
|
type LogLevel,
|
|
type LogSet,
|
|
} from '../../harness';
|
|
|
|
/** Go time.Duration.String() */
|
|
const GO_DURATION_RE = /^(\d+(\.\d+)?(h|m|s|ms|µs|ns))+$|^0s$/;
|
|
|
|
const SERVER_FUNCS = [
|
|
'app.execute',
|
|
'app.runServer',
|
|
'OpenDatabase',
|
|
'InitializeSchema',
|
|
'WebServer.Handler',
|
|
'WebServer.Serve',
|
|
'WebServer.logRequests',
|
|
'WebServer.handleContainers',
|
|
'authenticate',
|
|
'TokenStore.GetToken',
|
|
'AuditStore.RecordOperation',
|
|
'DockerClient.ListRunningContainers',
|
|
'WebServer.handleNotFound',
|
|
'WebServer.handleMethodNotAllowed',
|
|
];
|
|
|
|
const DEBUG_SERVER_MESSAGES = [
|
|
'configuration resolved',
|
|
'dispatch',
|
|
'database schema initialized',
|
|
'database opened',
|
|
'docker client created',
|
|
'routes registered',
|
|
'authentication result',
|
|
'audit row inserted',
|
|
'docker request started',
|
|
'docker request finished',
|
|
'shutdown requested, draining http server',
|
|
'http server shut down',
|
|
'database closed',
|
|
];
|
|
|
|
function expectOnlyLevels(logs: LogSet, min: LogLevel): void {
|
|
const allowed = visibleLevels(min);
|
|
const bad = logs.records.filter((r) => !allowed.includes(r.level as LogLevel));
|
|
expect(bad.map((r) => r.raw), `records below ${min}`).toEqual([]);
|
|
for (const r of logs.records) {
|
|
expect(r.time, `time attribute of ${r.raw}`).toMatch(LOG_TIME_RE);
|
|
expect(LOG_LEVELS).toContain(r.level as LogLevel);
|
|
}
|
|
}
|
|
|
|
for (const level of LOG_LEVELS) {
|
|
test(`server at LOG_LEVEL=${level}: emitted records match the level exactly`, async ({ cli, startServer, http }) => {
|
|
const active = await cli.tokenNew('logging probe');
|
|
const inactive = await cli.tokenNew('to be deleted');
|
|
await cli.tokenDelete(inactive);
|
|
const unknown = 'U'.repeat(43);
|
|
|
|
const server = await startServer({ logLevel: level, addr: '127.0.0.1' });
|
|
const fake = server.fakeDocker!.many(2);
|
|
|
|
// The same request sequence at every level
|
|
expectContainersResponse(await http.get(server.url(), { token: active }));
|
|
expectErrorResponse(await http.get(server.url()), 401);
|
|
expectErrorResponse(await http.get(server.url(), { token: unknown }), 401);
|
|
expectErrorResponse(await http.get(server.url(), { token: inactive }), 401);
|
|
expectErrorResponse(await http.get(server.url('/nope')), 404);
|
|
expectErrorResponse(await http.fetch(server.url(), { method: 'POST' }), 405);
|
|
fake.error500();
|
|
expectErrorResponse(await http.get(server.url(), { token: active }), 500);
|
|
fake.many(2);
|
|
|
|
const exit = await server.stop('SIGTERM');
|
|
expect(exit.exitCode).toBe(0);
|
|
expect(exit.stdout, 'server never writes to stdout').toBe('');
|
|
|
|
const logs = server.logs();
|
|
expect(logs.unparsed, 'every stderr line is a slog record').toEqual([]);
|
|
expectOnlyLevels(logs, level);
|
|
const shows = (l: LogLevel) => levelRank(l) >= levelRank(level);
|
|
|
|
// ERROR: request failures only
|
|
expect(logs.filter({ level: 'ERROR' }).map((r) => r.msg)).toEqual(['docker request failed']);
|
|
const err = logs.find({ level: 'ERROR', msg: 'docker request failed' })!;
|
|
expect(err.attrs.error, 'diagnostics stay in the logs').toContain('fake engine failure');
|
|
|
|
// WARN: nothing is expected from a healthy server
|
|
expect(logs.count({ level: 'WARN' })).toBe(0);
|
|
|
|
// INFO
|
|
const listening = logs.filter({ level: 'INFO', msg: 'server listening' });
|
|
const requests = logs.requests();
|
|
if (shows('INFO')) {
|
|
expect(listening).toHaveLength(1);
|
|
expect(listening[0].attrs.addr).toBe(`127.0.0.1:${server.port}`);
|
|
expect(listening[0].attrs.version).toBeTruthy();
|
|
expect(listening[0].attrs.commit).toBeTruthy();
|
|
expect(logs.filter({ level: 'INFO', msg: 'server stopped' })).toHaveLength(1);
|
|
expect(requests.map((r) => [r.level, r.attrs.method, r.attrs.path, r.attrs.status, r.attrs.origin])).toEqual([
|
|
['INFO', 'GET', '/api/v1/containers', '200', '127.0.0.1'],
|
|
['INFO', 'GET', '/api/v1/containers', '401', '127.0.0.1'],
|
|
['INFO', 'GET', '/api/v1/containers', '401', '127.0.0.1'],
|
|
['INFO', 'GET', '/api/v1/containers', '401', '127.0.0.1'],
|
|
['INFO', 'GET', '/nope', '404', '127.0.0.1'],
|
|
['INFO', 'POST', '/api/v1/containers', '405', '127.0.0.1'],
|
|
['INFO', 'GET', '/api/v1/containers', '500', '127.0.0.1'],
|
|
]);
|
|
for (const r of requests) {
|
|
expect(r.msg).toBe('this request has been made');
|
|
expect(r.attrs.duration).toMatch(GO_DURATION_RE);
|
|
expect(Object.keys(r.attrs).sort()).toEqual(['duration', 'method', 'origin', 'path', 'status']);
|
|
}
|
|
} else {
|
|
expect(listening, 'server listening hidden below INFO').toHaveLength(0);
|
|
expect(requests, '"this request has been made" hidden below INFO').toHaveLength(0);
|
|
expect(logs.count({ msg: 'server stopped' })).toBe(0);
|
|
expect(logs.count({ level: 'INFO' })).toBe(0);
|
|
}
|
|
|
|
// DEBUG
|
|
if (shows('DEBUG')) {
|
|
for (const m of DEBUG_SERVER_MESSAGES) expect(logs.count({ level: 'DEBUG', msg: m }), `DEBUG "${m}"`).toBeGreaterThan(0);
|
|
expect(logs.find({ msg: 'configuration resolved' })!.attrs).toEqual({
|
|
db_path: server.dbPath,
|
|
http_addr: '127.0.0.1',
|
|
http_port: String(server.port),
|
|
log_level: level,
|
|
});
|
|
expect(logs.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'server' });
|
|
expect(logs.find({ msg: 'docker client created' })!.attrs).toEqual({ host: 'unix:///var/run/docker.sock' });
|
|
expect(logs.find({ msg: 'routes registered' })!.attrs).toEqual({ route: 'GET /api/v1/containers' });
|
|
expect(logs.filter({ msg: 'authentication result' }).map((r) => r.attrs.result)).toEqual(['ok', 'missing_header', 'unknown_token', 'inactive_token', 'ok']);
|
|
for (const r of logs.filter({ msg: 'authentication result', attrs: { result: 'ok' } })) expect(r.attrs.token_id).toBe(tokenId(active));
|
|
expect(logs.filter({ msg: 'audit row inserted' }).map((r) => r.attrs)).toEqual([
|
|
{ token_id: tokenId(active), origin: '127.0.0.1', operation: 'GET containers' },
|
|
{ token_id: tokenId(active), origin: '127.0.0.1', operation: 'GET containers' },
|
|
]);
|
|
const finished = logs.filter({ msg: 'docker request finished' });
|
|
expect(finished.map((r) => [r.attrs.ok, r.attrs.containers])).toEqual([
|
|
['true', '2'],
|
|
['false', undefined],
|
|
]);
|
|
expect(logs.count({ msg: 'docker request started' })).toBe(2);
|
|
} else {
|
|
expect(logs.count({ level: 'DEBUG' })).toBe(0);
|
|
}
|
|
|
|
// TRACE
|
|
if (shows('TRACE')) {
|
|
for (const fn of SERVER_FUNCS) {
|
|
const entries = logs.count({ level: 'TRACE', msg: 'function entry', attrs: { func: fn } });
|
|
const exits = logs.count({ level: 'TRACE', msg: 'function exit', attrs: { func: fn } });
|
|
expect(entries, `function entry ${fn}`).toBeGreaterThan(0);
|
|
expect(exits, `function exit ${fn} balanced with entries`).toBe(entries);
|
|
}
|
|
// row-level records: token rows identified by token_id only, audit rows, containers
|
|
const reads = logs.filter({ level: 'TRACE', msg: 'row read', attrs: { table: 'tokens' } });
|
|
expect(reads.map((r) => [r.attrs.token_id, r.attrs.active])).toEqual([
|
|
[tokenId(active), 'true'],
|
|
[tokenId(inactive), 'false'],
|
|
[tokenId(active), 'true'],
|
|
]);
|
|
expect(reads[0].attrs.description).toBe('logging probe');
|
|
expect(reads[0].attrs.deleted_at).toBe('<nil>');
|
|
expect(reads[1].attrs.deleted_at).toMatch(/^\d{4}-.*Z$/);
|
|
expect(logs.filter({ level: 'TRACE', msg: 'row not found' }).map((r) => r.attrs)).toEqual([{ table: 'tokens', token_id: tokenId(unknown) }]);
|
|
const inserted = logs.filter({ level: 'TRACE', msg: 'row inserted', attrs: { table: 'operations' } });
|
|
expect(inserted).toHaveLength(2);
|
|
for (const r of inserted) {
|
|
expect(r.attrs.token_id).toBe(tokenId(active));
|
|
expect(r.attrs.origin).toBe('127.0.0.1');
|
|
expect(r.attrs.operation).toBe('GET containers');
|
|
expect(r.attrs.time).toMatch(/^\d{4}-.*Z$/);
|
|
}
|
|
expect(logs.filter({ level: 'TRACE', msg: 'container listed' }).map((r) => [r.attrs.names, r.attrs.state])).toEqual([
|
|
['[/fake-0]', 'running'],
|
|
['[/fake-1]', 'running'],
|
|
]);
|
|
} else {
|
|
expect(logs.count({ level: 'TRACE' })).toBe(0);
|
|
}
|
|
|
|
// Secrets / headers never logged at any level
|
|
for (const t of [active, inactive, unknown]) expect(server.stderr.includes(t), 'token value in logs').toBe(false);
|
|
expect(server.stderr).not.toContain('Bearer');
|
|
expect(server.stderr.toLowerCase()).not.toContain('authorization');
|
|
});
|
|
|
|
test(`CLI at LOG_LEVEL=${level}: token commands log exactly what the level allows`, async ({ cli }) => {
|
|
const env = { LOG_LEVEL: level };
|
|
const created = await cli.run(['token', 'new', 'cli level probe'], { env });
|
|
expect(created.exitCode).toBe(0);
|
|
const token = created.stdout.trim();
|
|
const listed = await cli.run(['token', 'list'], { env });
|
|
expect(listed.exitCode).toBe(0);
|
|
const deleted = await cli.run(['token', 'delete', token], { env });
|
|
expect(deleted.exitCode).toBe(0);
|
|
expect(deleted.stdout).toBe('');
|
|
const listedAll = await cli.run(['token', 'list', 'all'], { env });
|
|
expect(listedAll.exitCode).toBe(0);
|
|
const help = await cli.run(['help'], { env });
|
|
expect(help.exitCode).toBe(0);
|
|
expect(help.stdout, 'help: stdout is exactly the usage text at every level').toBe(USAGE_TEXT);
|
|
|
|
for (const r of [created, listed, deleted, listedAll, help]) {
|
|
expect(r.stderr.includes(token), 'token never in CLI logs').toBe(false);
|
|
const logs = parseLogs(r.stderr);
|
|
expect(logs.unparsed).toEqual([]);
|
|
expectOnlyLevels(logs, level);
|
|
if (levelRank(level) >= levelRank('INFO')) expect(r.stderr, 'successful CLI commands are silent at INFO and above').toBe('');
|
|
}
|
|
const c = parseLogs(created.stderr);
|
|
const d = parseLogs(deleted.stderr);
|
|
if (levelRank(level) <= levelRank('DEBUG')) {
|
|
expect(c.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' });
|
|
expect(c.find({ msg: 'cli dispatch' })!.attrs).toEqual({ command: 'token new' });
|
|
expect(c.find({ msg: 'token created' })!.attrs).toEqual({ token_id: tokenId(token) });
|
|
expect(c.find({ msg: 'cli command finished' })!.attrs).toEqual({ command: 'token new', ok: 'true' });
|
|
expect(c.has({ msg: 'database closed' })).toBe(true);
|
|
expect(parseLogs(listed.stderr).find({ msg: 'cli dispatch' })!.attrs).toEqual({ command: 'token list' });
|
|
// as implemented: `token list all` dispatches under the same command name
|
|
expect(parseLogs(listedAll.stderr).find({ msg: 'cli dispatch' })!.attrs).toEqual({ command: 'token list' });
|
|
expect(d.find({ msg: 'token deactivated' })!.attrs).toEqual({ token_id: tokenId(token) });
|
|
const h = parseLogs(help.stderr);
|
|
expect(h.find({ msg: 'dispatch' })!.attrs).toEqual({ mode: 'cli' });
|
|
expect(h.filter({ msg: 'cli dispatch' }).map((x) => x.attrs)).toEqual([{ command: 'help' }]);
|
|
expect(h.has({ msg: /^database / }), 'help never opens the database').toBe(false);
|
|
} else {
|
|
expect(help.stderr, 'help is silent above DEBUG').toBe('');
|
|
}
|
|
if (level === 'TRACE') {
|
|
for (const fn of ['app.execute', 'app.runTokenCommand', 'OpenDatabase', 'InitializeSchema', 'app.tokenNew', 'TokenStore.CreateToken']) {
|
|
expect(c.count({ msg: 'function entry', attrs: { func: fn } }), fn).toBe(1);
|
|
expect(c.count({ msg: 'function exit', attrs: { func: fn } }), fn).toBe(1);
|
|
}
|
|
const ins = c.find({ msg: 'row inserted', attrs: { table: 'tokens' } })!;
|
|
expect(ins.attrs).toMatchObject({ token_id: tokenId(token), description: 'cli level probe', active: 'true', deleted_at: '<nil>' });
|
|
expect(parseLogs(listed.stderr).find({ msg: 'row read' })!.attrs.token_id).toBe(tokenId(token));
|
|
// after the deletion: plain `token list` reads no row (SQL filter), `token list all` reads it
|
|
expect(parseLogs(listedAll.stderr).filter({ msg: 'row read' }).map((x) => x.attrs.token_id)).toEqual([tokenId(token)]);
|
|
expect(parseLogs(listedAll.stderr).find({ msg: 'row read' })!.attrs).toMatchObject({ active: 'false' });
|
|
const upd = d.find({ msg: 'row updated', attrs: { table: 'tokens' } })!;
|
|
expect(upd.attrs).toMatchObject({ token_id: tokenId(token), active_from: 'true', active_to: 'false' });
|
|
}
|
|
});
|
|
}
|
|
|
|
test('LOG_LEVEL is ASCII case-insensitive and defaults to INFO', async ({ cli, startServer, http }) => {
|
|
for (const [value, canonical] of [
|
|
['trace', 'TRACE'],
|
|
['Debug', 'DEBUG'],
|
|
['iNfO', 'INFO'],
|
|
['warn', 'WARN'],
|
|
['eRRoR', 'ERROR'],
|
|
] as const) {
|
|
const r = await cli.run(['token', 'list'], { env: { LOG_LEVEL: value } });
|
|
expect(r.exitCode, value).toBe(0);
|
|
const logs = parseLogs(r.stderr);
|
|
expectOnlyLevels(logs, canonical);
|
|
if (levelRank(canonical) <= levelRank('DEBUG')) expect(logs.find({ msg: 'configuration resolved' })!.attrs.log_level).toBe(canonical);
|
|
else expect(r.stderr).toBe('');
|
|
}
|
|
|
|
// Unset LOG_LEVEL → INFO
|
|
const token = await cli.tokenNew();
|
|
const server = await startServer({ logLevel: null });
|
|
expectContainersResponse(await http.get(server.url(), { token }));
|
|
expect((await server.stop()).exitCode).toBe(0);
|
|
const logs = server.logs();
|
|
expectOnlyLevels(logs, 'INFO');
|
|
expect(logs.requests()).toHaveLength(1);
|
|
expect(logs.has({ msg: 'server listening' })).toBe(true);
|
|
});
|