feat(cli): add help, token and audit commands

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.

e2e/tests/host/logging.spec.ts

@@ -0,0 +1,291 @@
+// 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);
+});