diff --git a/.changeset/177-observability-seam.md b/.changeset/177-observability-seam.md new file mode 100644 index 000000000..9349a9a2b --- /dev/null +++ b/.changeset/177-observability-seam.md @@ -0,0 +1,5 @@ +--- +type: Added +pr: 177 +--- +**Observability seam for Hub dispatch (#177)** — the Command Routing Hub now accepts an injected `DispatchLogger`. Default behaviour is silent on success and emits a structured JSON line to stderr on error. Opt-in file audit at `.planning/.gsd-trace.jsonl` is enabled via `GSD_AUDIT=1` env var or `config.audit.enabled: true`. Args are excluded from every emitted event by default (privacy); `GSD_AUDIT_ARGS=1` opts in. diff --git a/.gitignore b/.gitignore index 614296eeb..edfcac5ec 100644 --- a/.gitignore +++ b/.gitignore @@ -78,3 +78,6 @@ entities.json # Local scratch + Claude-test artifacts .scratch/ claude-test-command.md + +# Observability audit trail (issue #177) — append-only, local only +.planning/.gsd-trace.jsonl diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index 94174d79c..fcc735366 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -1096,9 +1096,11 @@ This resolves `gsd-planner` → `gpt-5.4` (xhigh), `gsd-executor` → `gpt-5.3-c |----------|---------| | `CLAUDE_CONFIG_DIR` | Override default config directory (`~/.claude/`) | | `GEMINI_API_KEY` | Detected by context monitor to switch hook event name | -| `WSL_DISTRO_NAME` | Detected by installer for WSL path handling | -| `GSD_SKIP_SCHEMA_CHECK` | Skip schema drift detection during execute-phase (v1.31) | +| `GSD_AUDIT` | Set to `1` to enable the dispatch audit file (`.planning/.gsd-trace.jsonl`) | +| `GSD_AUDIT_ARGS` | Set to `1` to include command args in audit/error events (omitted by default) | | `GSD_PROJECT` | Override project root for multi-project workspace support (v1.32) | +| `GSD_SKIP_SCHEMA_CHECK` | Skip schema drift detection during execute-phase (v1.31) | +| `WSL_DISTRO_NAME` | Detected by installer for WSL path handling | --- @@ -1109,3 +1111,51 @@ Save settings as global defaults for future projects: **Location:** `~/.gsd/defaults.json` When `/gsd-new-project` creates a new `config.json`, it reads global defaults and merges them as the starting configuration. Per-project settings always override globals. + +--- + +## Observability + +The Command Routing Hub emits a structured `DispatchEvent` after every dispatch. Default behaviour is **silent on success** and **one structured JSON line to stderr on error**. + +### Stderr error format + +When a dispatch fails, one JSON line is emitted to stderr: + +```json +{ "kind": "HandlerFailure", "traceId": "...", "command": "plan", "timestamp": "...", "message": "..." } +``` + +The `kind` field matches one of the Hub's error variants: `UnknownCommand`, `InvalidArgs`, `HandlerRefusal`, or `HandlerFailure`. Args are omitted by default (privacy); see `GSD_AUDIT_ARGS` below. + +### Audit trail (opt-in) + +Enable the append-only audit file to record every dispatch (success and error): + +**Via environment variable:** +```bash +GSD_AUDIT=1 gsd plan +``` + +**Via config (`config.audit.enabled`):** +```json +{ + "audit": { + "enabled": true + } +} +``` + +**Audit file location:** `.planning/.gsd-trace.jsonl` (gitignored) + +Each line is a full `DispatchEvent` JSON object. The file is append-only and never truncated; rotate or remove it manually when desired. + +### Args redaction + +By default, command args are **omitted** from all emitted events (both stderr errors and the audit file). To include args verbatim: + +```bash +GSD_AUDIT_ARGS=1 GSD_AUDIT=1 gsd plan --tdd +``` + +`GSD_AUDIT_ARGS` applies to both the stderr error line and the audit file simultaneously. diff --git a/get-shit-done/bin/lib/command-routing-hub.cjs b/get-shit-done/bin/lib/command-routing-hub.cjs index f51662431..2dc320952 100644 --- a/get-shit-done/bin/lib/command-routing-hub.cjs +++ b/get-shit-done/bin/lib/command-routing-hub.cjs @@ -1,7 +1,7 @@ 'use strict'; /** - * Command Routing Hub — issue #3788, simplified in #175, typed in #176. + * Command Routing Hub — issue #3788, simplified in #175, typed in #176, observability in #177. * * A pure-result dispatch hub that centralizes CJS routing, * the error taxonomy, and the no-throw contract that all command-family routers @@ -47,6 +47,10 @@ const ERROR_KINDS = Object.freeze({ HandlerFailure: 'HandlerFailure', }); +// ─── Observability imports ──────────────────────────────────────────────────── +const { makeDispatchEvent } = require('./observability/event.cjs'); +const { createNoOpLogger } = require('./observability/logger.cjs'); + // ─── Internal helpers ───────────────────────────────────────────────────────── /** @@ -202,17 +206,85 @@ function _validateErrResult(result) { * Nested map of family -> subcommand -> handler. * @property {Record} [manifest] - Map of family -> known subcommands. * Used for UnknownCommand detection. + * @property {{ onEvent(event: object): void }} [logger] - + * DispatchLogger to receive a DispatchEvent after every dispatch. + * Defaults to a no-op logger (silent). Use createDefaultLogger() for the + * reference implementation (stderr on error, opt-in file audit). */ +/** + * Safe stringify for logger-failure warnings — avoids circular-ref crashes. + * @param {unknown} value + * @returns {string} + */ +function _safeJsonForWarn(value) { + try { + return JSON.stringify(value); + } catch { + return String(value); + } +} + /** * Construct a CommandRoutingHub. * * @param {HubOptions} options * @returns {{ dispatch: (req: object) => HubResult }} */ -function createHub({ cjsRegistry, manifest } = {}) { +function createHub({ cjsRegistry, manifest, logger } = {}) { const _cjsRegistry = cjsRegistry; const _manifest = manifest; + // Default to no-op so callers that don't inject a logger get pure-silent behaviour. + // Consumers can opt into the reference impl by importing createDefaultLogger. + const _logger = (logger && typeof logger.onEvent === 'function') + ? logger + : createNoOpLogger(); + + /** + * Normalise a HubResult into the DispatchEvent result shape. + * + * HubResult ok path: { ok: true, data } → { kind: 'ok', data } + * HubResult err paths: { ok: false, kind, ...payload } → { kind, ...payload } + * + * @param {object} hubResult + * @returns {object} + */ + function _normaliseResult(hubResult) { + if (hubResult.ok) { + return { kind: 'ok', data: hubResult.data }; + } + // err variant: already has kind + typed payload + return hubResult; + } + + /** + * Emit a DispatchEvent to the injected logger. + * Logger errors NEVER propagate — they are caught and emitted as a warn line to stderr. + * + * @param {string} command - The dispatched command string. + * @param {unknown} args - The raw args from the request. + * @param {object} hubResult - The HubResult. + */ + function _notifyLogger(command, args, hubResult) { + try { + const eventResult = _normaliseResult(hubResult); + const event = makeDispatchEvent({ command, args, result: eventResult }); + _logger.onEvent(event); + } catch (logErr) { + // Logger must never break dispatch. Emit a degraded warn line. + try { + process.stderr.write( + _safeJsonForWarn({ + level: 'warn', + source: 'DispatchLogger', + message: 'logger.onEvent failed: ' + String(logErr && logErr.message || logErr), + }) + '\n' + ); + } catch { + // If even stderr.write fails, swallow silently — dispatch result is returned below. + } + } + } /** * Dispatch a command through the hub. @@ -221,17 +293,25 @@ function createHub({ cjsRegistry, manifest } = {}) { * @returns {HubResult} */ function dispatch(req) { + const { family, subcommand, args = [] } = req || {}; + const command = subcommand ? `${family} ${subcommand}` : String(family); + + let result; try { - return _dispatch(req); + result = _dispatch(req); } catch (err) { if (err instanceof Error) { - return makeHandlerFailure(err.message, err); + result = makeHandlerFailure(err.message, err); + } else { + // Finding 2: preserve non-Error throwables via a wrapper Error with .thrown + const wrapper = new Error('non-Error thrown: ' + _safeJson(err)); + wrapper.thrown = err; + result = makeHandlerFailure(String(err), wrapper); } - // Finding 2: preserve non-Error throwables via a wrapper Error with .thrown - const wrapper = new Error('non-Error thrown: ' + _safeJson(err)); - wrapper.thrown = err; - return makeHandlerFailure(String(err), wrapper); } + + _notifyLogger(command, args, result); + return result; } function _dispatch(req) { diff --git a/get-shit-done/bin/lib/observability/event.cjs b/get-shit-done/bin/lib/observability/event.cjs new file mode 100644 index 000000000..c2341dd54 --- /dev/null +++ b/get-shit-done/bin/lib/observability/event.cjs @@ -0,0 +1,47 @@ +'use strict'; + +/** + * DispatchEvent shape factory — issue #177 (ADR-0174 P1.3). + * + * Creates a structured event record for every Hub dispatch, used by + * DispatchLogger to emit stderr errors and opt-in file audit trails. + * + * Shape: + * traceId: string — UUID v4, generated per dispatch + * parentTraceId: undefined — always undefined in P1.3; P1.4 wires the composer + * command: string — the dispatched verb + * args?: unknown — only present when includeArgs === true + * result: { kind: 'ok' | 'UnknownCommand' | 'InvalidArgs' | 'HandlerRefusal' | 'HandlerFailure', ...payload } + * timestamp: string — ISO 8601 + */ + +const { randomUUID } = require('crypto'); + +/** + * Create a DispatchEvent. + * + * @param {object} opts + * @param {string} opts.command - The dispatched command verb. + * @param {unknown} [opts.args] - Raw args passed to the hub. + * @param {object} opts.result - The HubResult returned by the hub. + * @param {boolean} [opts.includeArgs=false] - When true, include args in the event. + * @param {string} [opts.parentTraceId] - Ignored in P1.3; always yields undefined. + * @returns {object} Immutable DispatchEvent record. + */ +function makeDispatchEvent({ command, args, result, includeArgs = false, parentTraceId: _ignored }) { + const event = { + traceId: randomUUID(), + parentTraceId: undefined, + command: String(command), + result, + timestamp: new Date().toISOString(), + }; + + if (includeArgs && args !== undefined) { + event.args = args; + } + + return Object.freeze(event); +} + +module.exports = { makeDispatchEvent }; diff --git a/get-shit-done/bin/lib/observability/logger.cjs b/get-shit-done/bin/lib/observability/logger.cjs new file mode 100644 index 000000000..0fd04c76e --- /dev/null +++ b/get-shit-done/bin/lib/observability/logger.cjs @@ -0,0 +1,174 @@ +'use strict'; + +/** + * DispatchLogger interface + default implementation — issue #177 (ADR-0174 P1.3). + * + * Interface: + * { onEvent(event: DispatchEvent): void } + * + * Default behaviour (createDefaultLogger): + * 1. Silent on success — no stdout/stderr when result.kind === 'ok'. + * 2. Structured JSON to stderr on error — one line per dispatch error. + * 3. Opt-in audit file — when GSD_AUDIT=1 OR config.audit.enabled===true, + * appends every event (success + error) as one JSON line to + * .planning/.gsd-trace.jsonl relative to `cwd`. Creates .planning/ if absent. + * 4. Args redaction — args omitted by default; included when GSD_AUDIT_ARGS=1. + * + * No-op logger (createNoOpLogger): + * Silent on all events. Used as the Hub default when no logger is injected. + */ + +const fs = require('fs'); +const path = require('path'); + +const { redactEvent, shouldIncludeArgs } = require('./redaction.cjs'); + +const AUDIT_FILE_NAME = '.gsd-trace.jsonl'; +const PLANNING_DIR = '.planning'; + +// ─── helpers ───────────────────────────────────────────────────────────────── + +/** + * Safely serialise a value to JSON, falling back to a placeholder on circular refs. + * @param {unknown} value + * @returns {string} + */ +function _safeStringify(value) { + try { + return JSON.stringify(value); + } catch { + return JSON.stringify({ _serializationError: true }); + } +} + +/** + * Determine whether the audit file should be written to. + * + * @param {{ audit?: { enabled?: boolean } } | undefined} config + * @returns {boolean} + */ +function _isAuditEnabled(config) { + if (process.env.GSD_AUDIT === '1') return true; + if (config && config.audit && config.audit.enabled === true) return true; + return false; +} + +/** + * Build the redacted plain object for the audit file. + * Preserves the full DispatchEvent structure. + * + * @param {object} event - DispatchEvent + * @returns {object} + */ +function _toAuditRecord(event) { + return redactEvent(event); +} + +/** + * Build the flattened stderr error line. + * + * Per ADR-0174 P1.3 contract: { "kind": "", "traceId": "", ...typedPayload } + * The result's kind is promoted to top-level and the typed payload fields are spread in. + * The `result` wrapper is removed. + * + * @param {object} event - DispatchEvent with an error result + * @returns {object} + */ +function _toStderrRecord(event) { + const redacted = redactEvent(event); + const { result, ...eventWithoutResult } = redacted; + // Flatten: top-level gets kind + typed payload fields from result + const { kind, ...typedPayload } = result; + return Object.assign({}, eventWithoutResult, { kind }, typedPayload); +} + +/** + * Append one JSON line to the audit file. + * Creates .planning/ directory if it does not exist. + * + * Uses synchronous fs API (crash-safe for v1 — dispatch is synchronous). + * + * @param {string} cwd - Project root directory. + * @param {object} event - Redacted DispatchEvent. + */ +function _appendAuditLine(cwd, event) { + const planningDir = path.join(cwd, PLANNING_DIR); + // Ensure the directory exists + if (!fs.existsSync(planningDir)) { + fs.mkdirSync(planningDir, { recursive: true }); + } + const auditPath = path.join(planningDir, AUDIT_FILE_NAME); + fs.appendFileSync(auditPath, _safeStringify(event) + '\n', 'utf8'); +} + +// ─── Public factories ───────────────────────────────────────────────────────── + +/** + * Create a no-op logger. All events are silently dropped. + * This is the Hub's default when no logger is injected by the caller. + * + * @returns {{ onEvent(event: object): void }} + */ +function createNoOpLogger() { + return { + onEvent(_event) { + // intentionally empty + }, + }; +} + +/** + * Create the default DispatchLogger. + * + * @param {object} [opts] + * @param {string} [opts.cwd=process.cwd()] - Project root; audit file is written relative to this. + * @param {object} [opts.config] - GSD config object. config.audit.enabled triggers audit. + * @returns {{ onEvent(event: object): void }} + */ +function createDefaultLogger({ cwd = process.cwd(), config } = {}) { + return { + /** + * @param {object} event - A DispatchEvent from the Hub. + */ + onEvent(event) { + const isOk = event && event.result && event.result.kind === 'ok'; + + // ── Audit file (both ok and error) ──────────────────────────────────── + if (_isAuditEnabled(config)) { + try { + const auditRecord = _toAuditRecord(event); + _appendAuditLine(cwd, auditRecord); + } catch (auditErr) { + // Audit errors must not surface to callers + process.stderr.write( + _safeStringify({ + level: 'warn', + source: 'DispatchLogger', + message: 'audit file write failed: ' + String(auditErr && auditErr.message || auditErr), + }) + '\n' + ); + } + } + + // ── Stderr on error ─────────────────────────────────────────────────── + if (!isOk) { + try { + const stderrRecord = _toStderrRecord(event); + process.stderr.write(_safeStringify(stderrRecord) + '\n'); + } catch (stderrErr) { + // Last-resort: we cannot throw from the logger + process.stderr.write( + _safeStringify({ + level: 'warn', + source: 'DispatchLogger', + message: 'stderr emit failed: ' + String(stderrErr && stderrErr.message || stderrErr), + }) + '\n' + ); + } + } + // ── Silent on success (no else branch needed) ───────────────────────── + }, + }; +} + +module.exports = { createDefaultLogger, createNoOpLogger }; diff --git a/get-shit-done/bin/lib/observability/redaction.cjs b/get-shit-done/bin/lib/observability/redaction.cjs new file mode 100644 index 000000000..82c88c6d5 --- /dev/null +++ b/get-shit-done/bin/lib/observability/redaction.cjs @@ -0,0 +1,50 @@ +'use strict'; + +/** + * Arg redaction policy — issue #177 (ADR-0174 P1.3). + * + * Privacy default: args are OMITTED from every emitted event (both stderr + * and file audit). Opt-in: set GSD_AUDIT_ARGS=1 to include args verbatim. + * + * This module is deliberately simple and has no side effects — redaction + * decisions are stateless reads of process.env at call time so that tests + * can toggle the env var without module-level caching issues. + */ + +/** + * Returns true when the caller has opted in to including args in events. + * Only GSD_AUDIT_ARGS === '1' enables inclusion; any other value (including + * empty string, 'true', 'yes') keeps the default of omitting args. + * + * @returns {boolean} + */ +function shouldIncludeArgs() { + return process.env.GSD_AUDIT_ARGS === '1'; +} + +/** + * Return a redacted copy of a DispatchEvent. + * + * If args should be omitted (default), strips the `args` field entirely. + * If args should be included (GSD_AUDIT_ARGS=1), passes the event through + * unchanged (args were already set by makeDispatchEvent with includeArgs:true, + * or absent — in which case they stay absent). + * + * The original event object is never mutated (it is frozen by makeDispatchEvent). + * + * @param {object} event - A DispatchEvent (frozen or plain). + * @returns {object} A new plain object with the same fields, minus args when redacted. + */ +function redactEvent(event) { + if (shouldIncludeArgs()) { + // Include path: return a shallow copy with args preserved if present + const copy = Object.assign({}, event); + return copy; + } + + // Exclude path: build a copy omitting `args` + const { args: _dropped, ...rest } = event; + return rest; +} + +module.exports = { shouldIncludeArgs, redactEvent }; diff --git a/tests/observability/event.test.cjs b/tests/observability/event.test.cjs new file mode 100644 index 000000000..1e9b98b76 --- /dev/null +++ b/tests/observability/event.test.cjs @@ -0,0 +1,155 @@ +'use strict'; + +/** + * Tests for DispatchEvent shape factory (issue #177). + * + * Each test exercises the real module code path and asserts on + * observable behaviour (return values). No mocks, no vacuous truths. + */ + +const { describe, test, beforeEach, afterEach } = require('node:test'); +const assert = require('node:assert/strict'); + +const { + makeDispatchEvent, +} = require('../../get-shit-done/bin/lib/observability/event.cjs'); + +describe('makeDispatchEvent — shape', () => { + test('returns an object with required top-level fields', () => { + const event = makeDispatchEvent({ + command: 'plan', + args: ['--tdd'], + result: { kind: 'ok', data: null }, + }); + + assert.ok(typeof event.traceId === 'string', 'traceId must be a string'); + assert.ok(typeof event.command === 'string', 'command must be a string'); + assert.ok(typeof event.timestamp === 'string', 'timestamp must be a string'); + assert.ok('result' in event, 'result must be present'); + }); + + test('traceId is a UUID v4 (format check)', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + }); + // UUID v4: xxxxxxxx-xxxx-4xxx-yxxx-xxxxxxxxxxxx + const uuidV4Re = /^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; + assert.match(event.traceId, uuidV4Re, `traceId '${event.traceId}' is not a valid UUID v4`); + }); + + test('each call produces a unique traceId', () => { + const a = makeDispatchEvent({ command: 'plan', result: { kind: 'ok', data: null } }); + const b = makeDispatchEvent({ command: 'plan', result: { kind: 'ok', data: null } }); + assert.notEqual(a.traceId, b.traceId, 'consecutive calls must produce different traceIds'); + }); + + test('parentTraceId is always undefined in P1.3', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: 'should-be-ignored', + }); + // P1.3: parentTraceId field exists but is always undefined + assert.strictEqual(event.parentTraceId, undefined, 'parentTraceId must be undefined in P1.3'); + }); + + test('command is set from input', () => { + const event = makeDispatchEvent({ + command: 'discuss', + result: { kind: 'ok', data: null }, + }); + assert.equal(event.command, 'discuss'); + }); + + test('timestamp is a valid ISO 8601 string', () => { + const before = Date.now(); + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + }); + const after = Date.now(); + const parsed = Date.parse(event.timestamp); + assert.ok(!isNaN(parsed), `timestamp '${event.timestamp}' must parse as a date`); + assert.ok(parsed >= before, 'timestamp must not be in the past'); + assert.ok(parsed <= after + 5, 'timestamp must not be in the future'); + }); + + test('result field is passed through', () => { + const result = { kind: 'UnknownCommand', command: 'bogus' }; + const event = makeDispatchEvent({ command: 'bogus', result }); + assert.deepStrictEqual(event.result, result); + }); +}); + +describe('makeDispatchEvent — args field', () => { + test('args is omitted when not provided', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + }); + assert.ok(!('args' in event), 'args must not be present when not supplied'); + }); + + test('args is omitted when provided (default redaction)', () => { + // The event factory itself does NOT decide to include args — that is the + // redaction layer's job. makeDispatchEvent simply stores args as supplied. + // By default (no includeArgs), args should NOT appear in the returned event. + const event = makeDispatchEvent({ + command: 'plan', + args: ['--foo', 'bar'], + result: { kind: 'ok', data: null }, + includeArgs: false, + }); + assert.ok(!('args' in event), 'args must be absent when includeArgs is false'); + }); + + test('args is included when includeArgs is true', () => { + const event = makeDispatchEvent({ + command: 'plan', + args: ['--foo', 'bar'], + result: { kind: 'ok', data: null }, + includeArgs: true, + }); + assert.ok('args' in event, 'args must be present when includeArgs is true'); + assert.deepStrictEqual(event.args, ['--foo', 'bar']); + }); +}); + +describe('makeDispatchEvent — result variants', () => { + test('ok result shape', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: 42 }, + }); + assert.equal(event.result.kind, 'ok'); + assert.equal(event.result.data, 42); + }); + + test('UnknownCommand result shape', () => { + const event = makeDispatchEvent({ + command: 'bogus', + result: { kind: 'UnknownCommand', command: 'bogus' }, + }); + assert.equal(event.result.kind, 'UnknownCommand'); + assert.equal(event.result.command, 'bogus'); + }); + + test('InvalidArgs result shape', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'InvalidArgs', arg: '--bad', reason: 'not recognised' }, + }); + assert.equal(event.result.kind, 'InvalidArgs'); + assert.equal(event.result.arg, '--bad'); + }); + + test('HandlerFailure result shape', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'HandlerFailure', message: 'boom' }, + }); + assert.equal(event.result.kind, 'HandlerFailure'); + assert.equal(event.result.message, 'boom'); + }); +}); diff --git a/tests/observability/hub-logger-integration.test.cjs b/tests/observability/hub-logger-integration.test.cjs new file mode 100644 index 000000000..9e2164440 --- /dev/null +++ b/tests/observability/hub-logger-integration.test.cjs @@ -0,0 +1,305 @@ +'use strict'; + +/** + * Integration tests for the Hub + DispatchLogger seam (issue #177). + * + * These tests verify that: + * 1. The Hub calls logger.onEvent exactly once per dispatch. + * 2. The event passed to the logger has the correct shape. + * 3. Logger errors do NOT propagate to the dispatch caller. + * 4. The no-op logger is used when no logger is injected. + * 5. A custom logger (injected via constructor) receives correct events. + * + * Real Hub code is used — no mocks of the Hub itself. + * Logger is a real tracking stub (records calls, no fs writes needed here). + */ + +const { describe, test, beforeEach, afterEach } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); +const os = require('os'); + +const { + createHub, + ERROR_KINDS, +} = require('../../get-shit-done/bin/lib/command-routing-hub.cjs'); + +const { + createDefaultLogger, + createNoOpLogger, +} = require('../../get-shit-done/bin/lib/observability/logger.cjs'); + +// ─── helpers ───────────────────────────────────────────────────────────────── + +/** Creates a logger stub that records every onEvent call. */ +function makeTrackingLogger() { + const calls = []; + return { + onEvent(event) { + calls.push(event); + }, + calls, + }; +} + +function makeTmpDir() { + return fs.mkdtempSync(path.join(os.tmpdir(), 'gsd-hub-logger-test-')); +} + +/** Capture all stderr writes during fn() */ +function captureStderr(fn) { + const chunks = []; + const originalWrite = process.stderr.write.bind(process.stderr); + process.stderr.write = (chunk, ...rest) => { + chunks.push(typeof chunk === 'string' ? chunk : chunk.toString('utf8')); + return originalWrite(chunk, ...rest); + }; + try { + fn(); + } finally { + process.stderr.write = originalWrite; + } + return chunks.join(''); +} + +function makeHub(logger) { + const registry = { + plan: { + '': () => ({ ok: true, data: 'done' }), + }, + discuss: { + '': () => ({ ok: false, kind: 'HandlerRefusal', reason: 'not now' }), + }, + broken: { + '': () => { throw new Error('handler exploded'); }, + }, + }; + const manifest = { + plan: [''], + discuss: [''], + broken: [''], + }; + return createHub({ cjsRegistry: registry, manifest, logger }); +} + +// ─── Hub calls logger.onEvent once per dispatch ─────────────────────────────── + +describe('Hub + logger — onEvent called per dispatch', () => { + test('onEvent called exactly once on successful dispatch', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + assert.equal(tracking.calls.length, 1, 'onEvent must be called exactly once'); + }); + + test('onEvent called exactly once on error dispatch', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'discuss', subcommand: '' }); + assert.equal(tracking.calls.length, 1, 'onEvent must be called exactly once on error'); + }); + + test('onEvent called exactly once when handler throws', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'broken', subcommand: '' }); + assert.equal(tracking.calls.length, 1, 'onEvent must be called even when handler throws'); + }); + + test('onEvent called once for unknown command', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'nonexistent', subcommand: '' }); + assert.equal(tracking.calls.length, 1); + }); + + test('multiple dispatches produce multiple onEvent calls (one per dispatch)', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + hub.dispatch({ family: 'discuss', subcommand: '' }); + hub.dispatch({ family: 'plan', subcommand: '' }); + assert.equal(tracking.calls.length, 3); + }); +}); + +// ─── Event shape passed to logger ──────────────────────────────────────────── + +describe('Hub + logger — event shape', () => { + test('event has traceId, command, result, timestamp on success', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + + const event = tracking.calls[0]; + assert.ok(typeof event.traceId === 'string', 'traceId must be a string'); + assert.ok(typeof event.command === 'string', 'command must be a string'); + assert.ok(typeof event.timestamp === 'string', 'timestamp must be a string'); + assert.ok('result' in event, 'result must be present'); + }); + + test('event.result.kind is "ok" for successful dispatch', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + assert.equal(tracking.calls[0].result.kind, 'ok'); + }); + + test('event.result.kind is the error kind for failed dispatch', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'discuss', subcommand: '' }); + assert.equal(tracking.calls[0].result.kind, 'HandlerRefusal'); + }); + + test('event.result.kind is HandlerFailure when handler throws', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'broken', subcommand: '' }); + assert.equal(tracking.calls[0].result.kind, 'HandlerFailure'); + }); + + test('event.command includes the family', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + assert.ok(tracking.calls[0].command.includes('plan'), 'command must reference the family'); + }); + + test('each dispatch has a unique traceId', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + hub.dispatch({ family: 'plan', subcommand: '' }); + assert.notEqual( + tracking.calls[0].traceId, + tracking.calls[1].traceId, + 'consecutive dispatches must produce unique traceIds' + ); + }); + + test('event.parentTraceId is undefined in P1.3', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + hub.dispatch({ family: 'plan', subcommand: '' }); + assert.strictEqual(tracking.calls[0].parentTraceId, undefined, + 'parentTraceId must be undefined in P1.3'); + }); +}); + +// ─── Logger errors do not break dispatch ──────────────────────────────────── + +describe('Hub + logger — logger errors are contained', () => { + test('dispatch still returns Result even if logger.onEvent throws', () => { + const throwingLogger = { + onEvent() { throw new Error('logger exploded'); }, + }; + const hub = makeHub(throwingLogger); + + let result; + // Must not throw + assert.doesNotThrow(() => { + result = hub.dispatch({ family: 'plan', subcommand: '' }); + }); + assert.ok(result.ok === true, 'dispatch must still return ok result despite logger failure'); + }); + + test('logger failure emits a warn line to stderr, not an uncaught exception', () => { + const throwingLogger = { + onEvent() { throw new Error('logger is broken'); }, + }; + const hub = makeHub(throwingLogger); + + const stderrOutput = captureStderr(() => { + hub.dispatch({ family: 'plan', subcommand: '' }); + }); + + // There should be some warning output + assert.ok(stderrOutput.length > 0, 'a warning must be emitted to stderr when logger fails'); + // It should be parseable JSON with level:warn + const parsed = JSON.parse(stderrOutput.trim().split('\n')[0]); + assert.equal(parsed.level, 'warn', 'logger failure warning must have level:warn'); + assert.equal(parsed.source, 'DispatchLogger'); + }); +}); + +// ─── No logger injected — defaults to no-op ────────────────────────────────── + +describe('Hub — default no-op when no logger injected', () => { + test('Hub works without a logger param (no throw)', () => { + const hub = createHub({ + cjsRegistry: { plan: { '': () => ({ ok: true, data: null }) } }, + manifest: { plan: [''] }, + }); + let result; + assert.doesNotThrow(() => { + result = hub.dispatch({ family: 'plan', subcommand: '' }); + }); + assert.ok(result.ok); + }); + + test('no stderr output for success when no logger injected', () => { + const hub = createHub({ + cjsRegistry: { plan: { '': () => ({ ok: true, data: null }) } }, + manifest: { plan: [''] }, + }); + const stderrOutput = captureStderr(() => { + hub.dispatch({ family: 'plan', subcommand: '' }); + }); + assert.equal(stderrOutput, '', 'no-op default must not produce any stderr'); + }); +}); + +// ─── End-to-end: createDefaultLogger with real Hub ────────────────────────── + +describe('Hub + createDefaultLogger — end-to-end', () => { + let tmpDir; + let savedAudit; + let savedAuditArgs; + + beforeEach(() => { + tmpDir = makeTmpDir(); + savedAudit = process.env.GSD_AUDIT; + savedAuditArgs = process.env.GSD_AUDIT_ARGS; + delete process.env.GSD_AUDIT; + delete process.env.GSD_AUDIT_ARGS; + }); + + afterEach(() => { + if (savedAudit === undefined) delete process.env.GSD_AUDIT; else process.env.GSD_AUDIT = savedAudit; + if (savedAuditArgs === undefined) delete process.env.GSD_AUDIT_ARGS; else process.env.GSD_AUDIT_ARGS = savedAuditArgs; + fs.rmSync(tmpDir, { recursive: true, force: true }); + }); + + test('silent on success with default logger', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const hub = makeHub(logger); + const stderrOutput = captureStderr(() => hub.dispatch({ family: 'plan', subcommand: '' })); + assert.equal(stderrOutput, '', 'must be silent on success'); + }); + + test('stderr line on error with default logger', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const hub = makeHub(logger); + const stderrOutput = captureStderr(() => hub.dispatch({ family: 'discuss', subcommand: '' })); + assert.ok(stderrOutput.trim().length > 0, 'must emit to stderr on error'); + const parsed = JSON.parse(stderrOutput.trim()); + assert.equal(parsed.kind, 'HandlerRefusal'); + }); + + test('audit file written when GSD_AUDIT=1', () => { + process.env.GSD_AUDIT = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + const hub = makeHub(logger); + hub.dispatch({ family: 'plan', subcommand: '' }); + + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + assert.ok(fs.existsSync(auditPath), 'audit file must exist after dispatch with GSD_AUDIT=1'); + + const line = fs.readFileSync(auditPath, 'utf8').trim(); + const parsed = JSON.parse(line); + assert.ok(typeof parsed.traceId === 'string'); + assert.equal(parsed.result.kind, 'ok'); + }); +}); diff --git a/tests/observability/logger.test.cjs b/tests/observability/logger.test.cjs new file mode 100644 index 000000000..4daa70c1c --- /dev/null +++ b/tests/observability/logger.test.cjs @@ -0,0 +1,339 @@ +'use strict'; + +/** + * Tests for DispatchLogger interface + default implementation (issue #177). + * + * All tests use real fs and real stderr capture (no mocks). + * Env vars are restored in afterEach. + * Temp dirs are created under os.tmpdir() and cleaned up in afterEach. + */ + +const { describe, test, beforeEach, afterEach } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); +const os = require('os'); + +const { + createDefaultLogger, + createNoOpLogger, +} = require('../../get-shit-done/bin/lib/observability/logger.cjs'); + +// ─── helpers ───────────────────────────────────────────────────────────────── + +function makeTmpDir() { + return fs.mkdtempSync(path.join(os.tmpdir(), 'gsd-logger-test-')); +} + +function captureStderr(fn) { + const chunks = []; + const originalWrite = process.stderr.write.bind(process.stderr); + process.stderr.write = (chunk, ...rest) => { + chunks.push(typeof chunk === 'string' ? chunk : chunk.toString('utf8')); + return originalWrite(chunk, ...rest); + }; + try { + fn(); + } finally { + process.stderr.write = originalWrite; + } + return chunks.join(''); +} + +function makeOkEvent(overrides = {}) { + return Object.assign({ + traceId: 'test-trace-id', + parentTraceId: undefined, + command: 'plan', + result: { kind: 'ok', data: null }, + timestamp: '2026-01-01T00:00:00.000Z', + }, overrides); +} + +function makeErrEvent(kindPayload, overrides = {}) { + return Object.assign({ + traceId: 'test-trace-id', + parentTraceId: undefined, + command: 'plan', + result: kindPayload, + timestamp: '2026-01-01T00:00:00.000Z', + }, overrides); +} + +// ─── createNoOpLogger ──────────────────────────────────────────────────────── + +describe('createNoOpLogger', () => { + test('returns an object with onEvent', () => { + const logger = createNoOpLogger(); + assert.ok(typeof logger.onEvent === 'function', 'onEvent must be a function'); + }); + + test('onEvent does not throw on ok result', () => { + const logger = createNoOpLogger(); + assert.doesNotThrow(() => logger.onEvent(makeOkEvent())); + }); + + test('onEvent does not throw on error result', () => { + const logger = createNoOpLogger(); + assert.doesNotThrow(() => + logger.onEvent(makeErrEvent({ kind: 'UnknownCommand', command: 'bogus' })) + ); + }); + + test('onEvent does not write to stderr', () => { + const logger = createNoOpLogger(); + const output = captureStderr(() => logger.onEvent(makeOkEvent())); + assert.equal(output, '', 'no-op logger must not write to stderr'); + }); +}); + +// ─── createDefaultLogger — silent on success ───────────────────────────────── + +describe('createDefaultLogger — silent on success', () => { + let tmpDir; + let savedAudit; + let savedAuditArgs; + + beforeEach(() => { + tmpDir = makeTmpDir(); + savedAudit = process.env.GSD_AUDIT; + savedAuditArgs = process.env.GSD_AUDIT_ARGS; + delete process.env.GSD_AUDIT; + delete process.env.GSD_AUDIT_ARGS; + }); + + afterEach(() => { + if (savedAudit === undefined) delete process.env.GSD_AUDIT; else process.env.GSD_AUDIT = savedAudit; + if (savedAuditArgs === undefined) delete process.env.GSD_AUDIT_ARGS; else process.env.GSD_AUDIT_ARGS = savedAuditArgs; + fs.rmSync(tmpDir, { recursive: true, force: true }); + }); + + test('no stderr output on ok result', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const stderrOutput = captureStderr(() => logger.onEvent(makeOkEvent())); + assert.equal(stderrOutput, '', 'must not write to stderr on ok result'); + }); + + test('no audit file created on ok result (no GSD_AUDIT)', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + logger.onEvent(makeOkEvent()); + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + assert.ok(!fs.existsSync(auditPath), 'audit file must not be created without GSD_AUDIT=1'); + }); +}); + +// ─── createDefaultLogger — stderr on error ────────────────────────────────── + +describe('createDefaultLogger — stderr on error', () => { + let tmpDir; + let savedAudit; + let savedAuditArgs; + + beforeEach(() => { + tmpDir = makeTmpDir(); + savedAudit = process.env.GSD_AUDIT; + savedAuditArgs = process.env.GSD_AUDIT_ARGS; + delete process.env.GSD_AUDIT; + delete process.env.GSD_AUDIT_ARGS; + }); + + afterEach(() => { + if (savedAudit === undefined) delete process.env.GSD_AUDIT; else process.env.GSD_AUDIT = savedAudit; + if (savedAuditArgs === undefined) delete process.env.GSD_AUDIT_ARGS; else process.env.GSD_AUDIT_ARGS = savedAuditArgs; + fs.rmSync(tmpDir, { recursive: true, force: true }); + }); + + test('emits exactly one JSON line to stderr on error', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const errEvent = makeErrEvent({ kind: 'UnknownCommand', command: 'bogus' }); + const stderrOutput = captureStderr(() => logger.onEvent(errEvent)); + + // Must be exactly one non-empty line + const lines = stderrOutput.split('\n').filter(l => l.trim().length > 0); + assert.equal(lines.length, 1, `expected 1 line, got ${lines.length}: ${stderrOutput}`); + }); + + test('stderr line is valid JSON', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const errEvent = makeErrEvent({ kind: 'HandlerFailure', message: 'boom' }); + let stderrOutput = ''; + stderrOutput = captureStderr(() => logger.onEvent(errEvent)); + + const line = stderrOutput.trim(); + let parsed; + assert.doesNotThrow(() => { parsed = JSON.parse(line); }, `stderr line must be valid JSON, got: ${line}`); + assert.ok(parsed !== null && typeof parsed === 'object'); + }); + + test('stderr JSON contains kind field matching result kind', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const errEvent = makeErrEvent({ kind: 'HandlerRefusal', reason: 'refused' }); + const stderrOutput = captureStderr(() => logger.onEvent(errEvent)); + const parsed = JSON.parse(stderrOutput.trim()); + assert.equal(parsed.kind, 'HandlerRefusal'); + }); + + test('stderr JSON contains traceId from the event', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const errEvent = makeErrEvent({ kind: 'UnknownCommand', command: 'bogus' }); + errEvent.traceId = 'specific-trace-id-123'; + const stderrOutput = captureStderr(() => logger.onEvent(errEvent)); + const parsed = JSON.parse(stderrOutput.trim()); + assert.equal(parsed.traceId, 'specific-trace-id-123'); + }); + + test('stderr JSON does not contain args by default (redaction)', () => { + const logger = createDefaultLogger({ cwd: tmpDir }); + const errEvent = makeErrEvent({ kind: 'InvalidArgs', arg: '--bad', reason: 'oops' }); + errEvent.args = ['--bad', 'value']; + const stderrOutput = captureStderr(() => logger.onEvent(errEvent)); + const parsed = JSON.parse(stderrOutput.trim()); + assert.ok(!('args' in parsed), 'args must be redacted from stderr output by default'); + }); + + test('stderr JSON includes args when GSD_AUDIT_ARGS=1', () => { + process.env.GSD_AUDIT_ARGS = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + const errEvent = Object.assign( + makeErrEvent({ kind: 'InvalidArgs', arg: '--bad', reason: 'oops' }), + { args: ['--bad', 'value'] } + ); + const stderrOutput = captureStderr(() => logger.onEvent(errEvent)); + const parsed = JSON.parse(stderrOutput.trim()); + assert.ok('args' in parsed, 'args must appear in stderr when GSD_AUDIT_ARGS=1'); + assert.deepStrictEqual(parsed.args, ['--bad', 'value']); + }); + + test('no stderr output on ok result even when GSD_AUDIT=1', () => { + process.env.GSD_AUDIT = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + const stderrOutput = captureStderr(() => logger.onEvent(makeOkEvent())); + assert.equal(stderrOutput, '', 'ok result must never produce stderr output'); + }); +}); + +// ─── createDefaultLogger — audit file ─────────────────────────────────────── + +describe('createDefaultLogger — audit file', () => { + let tmpDir; + let savedAudit; + let savedAuditArgs; + + beforeEach(() => { + tmpDir = makeTmpDir(); + savedAudit = process.env.GSD_AUDIT; + savedAuditArgs = process.env.GSD_AUDIT_ARGS; + delete process.env.GSD_AUDIT; + delete process.env.GSD_AUDIT_ARGS; + }); + + afterEach(() => { + if (savedAudit === undefined) delete process.env.GSD_AUDIT; else process.env.GSD_AUDIT = savedAudit; + if (savedAuditArgs === undefined) delete process.env.GSD_AUDIT_ARGS; else process.env.GSD_AUDIT_ARGS = savedAuditArgs; + fs.rmSync(tmpDir, { recursive: true, force: true }); + }); + + test('creates .planning/.gsd-trace.jsonl when GSD_AUDIT=1 (ok result)', () => { + process.env.GSD_AUDIT = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + logger.onEvent(makeOkEvent()); + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + assert.ok(fs.existsSync(auditPath), 'audit file must be created when GSD_AUDIT=1'); + }); + + test('creates .planning/ directory if absent', () => { + process.env.GSD_AUDIT = '1'; + // tmpDir has no .planning/ subdirectory + assert.ok(!fs.existsSync(path.join(tmpDir, '.planning'))); + const logger = createDefaultLogger({ cwd: tmpDir }); + logger.onEvent(makeOkEvent()); + assert.ok(fs.existsSync(path.join(tmpDir, '.planning'))); + }); + + test('audit file contains one valid JSON line per event', () => { + process.env.GSD_AUDIT = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + logger.onEvent(makeOkEvent({ traceId: 'a1' })); + logger.onEvent(makeOkEvent({ traceId: 'a2' })); + + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + const content = fs.readFileSync(auditPath, 'utf8'); + const lines = content.split('\n').filter(l => l.trim().length > 0); + assert.equal(lines.length, 2, `expected 2 lines, got ${lines.length}`); + + const parsed0 = JSON.parse(lines[0]); + const parsed1 = JSON.parse(lines[1]); + assert.equal(parsed0.traceId, 'a1'); + assert.equal(parsed1.traceId, 'a2'); + }); + + test('audit file is append-only (second run adds to existing content)', () => { + process.env.GSD_AUDIT = '1'; + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + + const logger1 = createDefaultLogger({ cwd: tmpDir }); + logger1.onEvent(makeOkEvent({ traceId: 'first' })); + + const logger2 = createDefaultLogger({ cwd: tmpDir }); + logger2.onEvent(makeOkEvent({ traceId: 'second' })); + + const content = fs.readFileSync(auditPath, 'utf8'); + const lines = content.split('\n').filter(l => l.trim().length > 0); + assert.equal(lines.length, 2, 'both events must appear (append-only)'); + assert.equal(JSON.parse(lines[0]).traceId, 'first'); + assert.equal(JSON.parse(lines[1]).traceId, 'second'); + }); + + test('audit file contains both ok and error events', () => { + process.env.GSD_AUDIT = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + logger.onEvent(makeOkEvent({ traceId: 'ok-event' })); + logger.onEvent(makeErrEvent({ kind: 'HandlerFailure', message: 'boom' }, { traceId: 'err-event' })); + + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + const content = fs.readFileSync(auditPath, 'utf8'); + const lines = content.split('\n').filter(l => l.trim().length > 0); + assert.equal(lines.length, 2); + + const traceIds = lines.map(l => JSON.parse(l).traceId); + assert.ok(traceIds.includes('ok-event'), 'ok event must be in audit file'); + assert.ok(traceIds.includes('err-event'), 'error event must be in audit file'); + }); + + test('audit file does NOT contain args by default', () => { + process.env.GSD_AUDIT = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + const event = Object.assign(makeOkEvent(), { args: ['secret-arg'] }); + logger.onEvent(event); + + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + const content = fs.readFileSync(auditPath, 'utf8'); + const parsed = JSON.parse(content.trim()); + assert.ok(!('args' in parsed), 'args must be redacted from audit file by default'); + }); + + test('audit file DOES contain args when GSD_AUDIT_ARGS=1', () => { + process.env.GSD_AUDIT = '1'; + process.env.GSD_AUDIT_ARGS = '1'; + const logger = createDefaultLogger({ cwd: tmpDir }); + const event = Object.assign(makeOkEvent(), { args: ['visible-arg'] }); + logger.onEvent(event); + + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + const content = fs.readFileSync(auditPath, 'utf8'); + const parsed = JSON.parse(content.trim()); + assert.ok('args' in parsed, 'args must appear in audit file when GSD_AUDIT_ARGS=1'); + assert.deepStrictEqual(parsed.args, ['visible-arg']); + }); + + test('config.audit.enabled === true triggers audit file (without GSD_AUDIT env)', () => { + // GSD_AUDIT is not set, but config says enabled + const logger = createDefaultLogger({ cwd: tmpDir, config: { audit: { enabled: true } } }); + logger.onEvent(makeOkEvent({ traceId: 'config-triggered' })); + + const auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + assert.ok(fs.existsSync(auditPath), 'audit file must be created when config.audit.enabled=true'); + const parsed = JSON.parse(fs.readFileSync(auditPath, 'utf8').trim()); + assert.equal(parsed.traceId, 'config-triggered'); + }); +}); diff --git a/tests/observability/redaction.test.cjs b/tests/observability/redaction.test.cjs new file mode 100644 index 000000000..bcd8f29e2 --- /dev/null +++ b/tests/observability/redaction.test.cjs @@ -0,0 +1,150 @@ +'use strict'; + +/** + * Tests for arg redaction policy (issue #177). + * + * Redaction decides whether args appear in emitted events based on + * the GSD_AUDIT_ARGS env var. Tests use real env manipulation and + * restore state in afterEach. No mocks. + */ + +const { describe, test, beforeEach, afterEach } = require('node:test'); +const assert = require('node:assert/strict'); + +const { + shouldIncludeArgs, + redactEvent, +} = require('../../get-shit-done/bin/lib/observability/redaction.cjs'); + +describe('shouldIncludeArgs', () => { + let originalEnv; + + beforeEach(() => { + originalEnv = process.env.GSD_AUDIT_ARGS; + delete process.env.GSD_AUDIT_ARGS; + }); + + afterEach(() => { + if (originalEnv === undefined) { + delete process.env.GSD_AUDIT_ARGS; + } else { + process.env.GSD_AUDIT_ARGS = originalEnv; + } + }); + + test('returns false when GSD_AUDIT_ARGS is not set', () => { + assert.strictEqual(shouldIncludeArgs(), false); + }); + + test('returns false when GSD_AUDIT_ARGS is empty string', () => { + process.env.GSD_AUDIT_ARGS = ''; + assert.strictEqual(shouldIncludeArgs(), false); + }); + + test('returns false when GSD_AUDIT_ARGS is "0"', () => { + process.env.GSD_AUDIT_ARGS = '0'; + assert.strictEqual(shouldIncludeArgs(), false); + }); + + test('returns true when GSD_AUDIT_ARGS is "1"', () => { + process.env.GSD_AUDIT_ARGS = '1'; + assert.strictEqual(shouldIncludeArgs(), true); + }); + + test('returns false for any other non-1 value', () => { + process.env.GSD_AUDIT_ARGS = 'yes'; + assert.strictEqual(shouldIncludeArgs(), false); + + process.env.GSD_AUDIT_ARGS = 'true'; + assert.strictEqual(shouldIncludeArgs(), false); + }); +}); + +describe('redactEvent', () => { + let originalEnv; + + beforeEach(() => { + originalEnv = process.env.GSD_AUDIT_ARGS; + delete process.env.GSD_AUDIT_ARGS; + }); + + afterEach(() => { + if (originalEnv === undefined) { + delete process.env.GSD_AUDIT_ARGS; + } else { + process.env.GSD_AUDIT_ARGS = originalEnv; + } + }); + + test('strips args from event when GSD_AUDIT_ARGS is not set', () => { + const event = Object.freeze({ + traceId: 'abc', + command: 'plan', + args: ['--foo', 'bar'], + result: { kind: 'ok', data: null }, + timestamp: new Date().toISOString(), + }); + const redacted = redactEvent(event); + assert.ok(!('args' in redacted), 'args must be absent after redaction'); + assert.equal(redacted.command, 'plan'); + assert.equal(redacted.traceId, 'abc'); + }); + + test('preserves all other fields after redaction', () => { + const event = Object.freeze({ + traceId: 'xyz', + parentTraceId: undefined, + command: 'discuss', + args: ['--mode', 'fast'], + result: { kind: 'HandlerRefusal', reason: 'nope' }, + timestamp: '2026-01-01T00:00:00.000Z', + }); + const redacted = redactEvent(event); + assert.equal(redacted.traceId, 'xyz'); + assert.equal(redacted.command, 'discuss'); + assert.equal(redacted.timestamp, '2026-01-01T00:00:00.000Z'); + assert.deepStrictEqual(redacted.result, { kind: 'HandlerRefusal', reason: 'nope' }); + }); + + test('includes args when GSD_AUDIT_ARGS=1', () => { + process.env.GSD_AUDIT_ARGS = '1'; + const event = Object.freeze({ + traceId: 'abc', + command: 'plan', + args: ['--foo', 'bar'], + result: { kind: 'ok', data: null }, + timestamp: new Date().toISOString(), + }); + const redacted = redactEvent(event); + assert.ok('args' in redacted, 'args must be present when GSD_AUDIT_ARGS=1'); + assert.deepStrictEqual(redacted.args, ['--foo', 'bar']); + }); + + test('event without args field stays without args after redaction', () => { + const event = Object.freeze({ + traceId: 'abc', + command: 'plan', + result: { kind: 'ok', data: null }, + timestamp: new Date().toISOString(), + }); + const redacted = redactEvent(event); + assert.ok(!('args' in redacted), 'args should not appear if original event had none'); + }); + + test('returns a new object, not a mutation of the original frozen event', () => { + const event = Object.freeze({ + traceId: 'abc', + command: 'plan', + args: ['secret'], + result: { kind: 'ok', data: null }, + timestamp: new Date().toISOString(), + }); + const redacted = redactEvent(event); + // Original must still have args + assert.ok('args' in event); + // Redacted must not have args + assert.ok(!('args' in redacted)); + // They must be different object references + assert.ok(redacted !== event); + }); +});