From 5f3eb4286478e12fbb6edb1845aade783d27444c Mon Sep 17 00:00:00 2001 From: Tom Boucher Date: Sun, 24 May 2026 16:32:28 -0400 Subject: [PATCH] =?UTF-8?q?feat(observability):=20propagate=20parentTraceI?= =?UTF-8?q?d=20on=20DispatchEvent=20=E2=80=94=20ADR-0174=20SDK=20retiremen?= =?UTF-8?q?t=20Phase=201.4=20(#178)=20(#225)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * test(#178): update DispatchEvent factory tests to propagate parentTraceId P1.3 test 'parentTraceId is always undefined' replaced with four P1.4 contracts: absent → undefined, string → propagated, null → undefined, non-string → undefined (defensive normalization policy). Co-Authored-By: Claude Sonnet 4.6 * feat(#178): propagate parentTraceId through DispatchEvent factory Stop ignoring the parentTraceId parameter added as a forward-compat hook in P1.3. Defensive normalization: only non-null strings are propagated; null, non-string values, and absent callers all yield undefined, keeping P1.3 behavior intact for all existing dispatch call sites. Co-Authored-By: Claude Sonnet 4.6 * test(#178): add Hub-level parentTraceId propagation tests Four new assertions: req.parentTraceId propagates to event, absent → undefined (P1.3 regression), shared parentTraceId across multiple dispatches, and unique traceId invariant despite shared parentTraceId. Co-Authored-By: Claude Sonnet 4.6 * feat(#178): plumb parentTraceId through Hub dispatch and _notifyLogger dispatch() now reads req.parentTraceId and passes it to _notifyLogger, which forwards it to makeDispatchEvent. Backward-compatible: callers that omit parentTraceId emit events with parentTraceId: undefined, identical to P1.3 behavior. Co-Authored-By: Claude Sonnet 4.6 * test(#178): add trace correlation end-to-end test Dispatches a root command then 3 children with parentTraceId=rootTraceId. Reads the real .gsd-trace.jsonl audit file and verifies: 4 events total, root has no parentTraceId, all children carry rootTraceId, all traceIds unique, JS filter returns exactly the 3 children given the root's traceId. Co-Authored-By: Claude Sonnet 4.6 * docs(#178): document traceId/parentTraceId in audit file Update Observability section to note that audit events now carry both traceId and parentTraceId, and explain the correlation filter pattern. Note that leaf dispatches emit parentTraceId: undefined until the Phase 2 composer wires it automatically. Co-Authored-By: Claude Sonnet 4.6 * chore(#178): add changeset for trace correlation seam Co-Authored-By: Claude Sonnet 4.6 * test(#178): cover invalid parentTraceId values in DispatchEvent factory Adds 9 new test cases for UUID v4 validation of parentTraceId: empty string, whitespace, non-UUID, oversized, UUID v1, missing-hyphen, extra-char (all dropped to undefined), plus UPPERCASE and lowercase v4 (both propagated). Tests are intentionally red until the implementation commit that follows. Co-Authored-By: Claude Sonnet 4.6 * feat(#178): validate parentTraceId against UUID v4 before propagation Adds UUID_V4_REGEX constant and isValidParentTraceId() helper to event.cjs. makeDispatchEvent now silently coerces any parentTraceId that fails the UUID v4 check (wrong version nibble, wrong variant, missing hyphens, oversized, empty, etc.) to undefined. No stderr warn is emitted — the factory remains pure and side-effect-free. Closes the correlation- poisoning vector identified in the Codex adversarial review of PR #225. Co-Authored-By: Claude Sonnet 4.6 * test(#178): assert Hub silently drops invalid parentTraceId at the seam Adds two tests to hub-logger-integration.test.cjs: 1. dispatch with 'junk' parentTraceId emits event with parentTraceId===undefined. 2. The logger-failure warn path is NOT triggered — the factory coerces the bad value before onEvent is called, confirmed by zero stderr output even when a logger that would throw on non-undefined parentTraceId is installed. Co-Authored-By: Claude Sonnet 4.6 * test(#178): assert invalid parentTraceId does not poison correlation siblings Adds one test to trace-correlation.test.cjs: dispatches a root, a valid child (parentTraceId = rootTraceId), and an invalid child (parentTraceId = 'junk'). Asserts: valid child carries correct parentTraceId, invalid child has parentTraceId dropped to undefined, filtering by rootTraceId yields exactly 1 event (the valid child only), and all 3 events have unique traceIds. Uses an isolated Hub + tmpdir to avoid shared fixture interference. Co-Authored-By: Claude Sonnet 4.6 * docs(#178): document UUID v4 contract for parentTraceId Appends one sentence to the Observability audit-trail paragraph in CONFIGURATION.md: parentTraceId must be canonical UUID v4 (RFC 4122); values that don't match are silently dropped from audit output. No section restructuring — single sentence addition only. Co-Authored-By: Claude Sonnet 4.6 --------- Co-authored-by: Claude Sonnet 4.6 --- .changeset/178-trace-id-propagation.md | 5 + docs/CONFIGURATION.md | 2 +- get-shit-done/bin/lib/command-routing-hub.cjs | 15 +- get-shit-done/bin/lib/observability/event.cjs | 47 +++- tests/dispatch/trace-correlation.test.cjs | 227 ++++++++++++++++++ tests/observability/event.test.cjs | 148 +++++++++++- .../hub-logger-integration.test.cjs | 81 ++++++- 7 files changed, 505 insertions(+), 20 deletions(-) create mode 100644 .changeset/178-trace-id-propagation.md create mode 100644 tests/dispatch/trace-correlation.test.cjs diff --git a/.changeset/178-trace-id-propagation.md b/.changeset/178-trace-id-propagation.md new file mode 100644 index 000000000..e7abe5d0f --- /dev/null +++ b/.changeset/178-trace-id-propagation.md @@ -0,0 +1,5 @@ +--- +type: Added +pr: 178 +--- +**`DispatchEvent` now propagates `parentTraceId` (#178)** — every `DispatchEvent` already carries a `traceId` (P1.3). `Hub.dispatch(req)` now accepts an optional `req.parentTraceId`; when present, it appears on the emitted event. This is the seam through which a future init-composer (Phase 2) will correlate child dispatches with their parent. Backward compatible — leaf dispatches that don't set `parentTraceId` emit events with `parentTraceId: undefined` exactly as in P1.3. diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index fcc735366..03d6b5a82 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -1148,7 +1148,7 @@ GSD_AUDIT=1 gsd plan **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. +Each line is a full `DispatchEvent` JSON object containing both `traceId` (a unique UUID v4 per dispatch) and `parentTraceId` (present when a caller passes `req.parentTraceId` into `Hub.dispatch`). A future init-composer (Phase 2) will wire `parentTraceId` automatically so that all child dispatches of a single top-level invocation share a common parent; until then, leaf dispatches emit `parentTraceId: undefined`. You can correlate child events to a parent by filtering the audit file on `parentTraceId === `. The file is append-only and never truncated; rotate or remove it manually when desired. `parentTraceId` must be a canonical UUID v4 (RFC 4122, format `xxxxxxxx-xxxx-4xxx-[89ab]xxx-xxxxxxxxxxxx`); values that do not match this format are silently dropped from the emitted event and will not appear in audit output. ### Args redaction diff --git a/get-shit-done/bin/lib/command-routing-hub.cjs b/get-shit-done/bin/lib/command-routing-hub.cjs index 2dc320952..e9ae37deb 100644 --- a/get-shit-done/bin/lib/command-routing-hub.cjs +++ b/get-shit-done/bin/lib/command-routing-hub.cjs @@ -261,14 +261,15 @@ function createHub({ cjsRegistry, manifest, logger } = {}) { * 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. + * @param {string} command - The dispatched command string. + * @param {unknown} args - The raw args from the request. + * @param {object} hubResult - The HubResult. + * @param {string} [parentTraceId] - Optional parent trace ID from the request (P1.4). */ - function _notifyLogger(command, args, hubResult) { + function _notifyLogger(command, args, hubResult, parentTraceId) { try { const eventResult = _normaliseResult(hubResult); - const event = makeDispatchEvent({ command, args, result: eventResult }); + const event = makeDispatchEvent({ command, args, result: eventResult, parentTraceId }); _logger.onEvent(event); } catch (logErr) { // Logger must never break dispatch. Emit a degraded warn line. @@ -293,7 +294,7 @@ function createHub({ cjsRegistry, manifest, logger } = {}) { * @returns {HubResult} */ function dispatch(req) { - const { family, subcommand, args = [] } = req || {}; + const { family, subcommand, args = [], parentTraceId } = req || {}; const command = subcommand ? `${family} ${subcommand}` : String(family); let result; @@ -310,7 +311,7 @@ function createHub({ cjsRegistry, manifest, logger } = {}) { } } - _notifyLogger(command, args, result); + _notifyLogger(command, args, result, parentTraceId); return result; } diff --git a/get-shit-done/bin/lib/observability/event.cjs b/get-shit-done/bin/lib/observability/event.cjs index c2341dd54..1a01c5a44 100644 --- a/get-shit-done/bin/lib/observability/event.cjs +++ b/get-shit-done/bin/lib/observability/event.cjs @@ -1,14 +1,17 @@ 'use strict'; /** - * DispatchEvent shape factory — issue #177 (ADR-0174 P1.3). + * DispatchEvent shape factory — issue #177 (ADR-0174 P1.3), extended in #178 (P1.4). * * 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 + * traceId: string — UUID v4, generated per dispatch + * parentTraceId: string|undefined — propagated from the caller when it is a canonical UUID v4 + * (RFC 4122); invalid values are silently coerced to undefined. + * Enables a future init-composer (Phase 2) to correlate child + * dispatches to their parent via the audit file. * command: string — the dispatched verb * args?: unknown — only present when includeArgs === true * result: { kind: 'ok' | 'UnknownCommand' | 'InvalidArgs' | 'HandlerRefusal' | 'HandlerFailure', ...payload } @@ -17,6 +20,29 @@ const { randomUUID } = require('crypto'); +/** + * Canonical UUID v4 regex (RFC 4122). + * - 36 characters total (32 hex + 4 hyphens) + * - Version nibble: 4 + * - Variant bits: [89ab] + * - Case-insensitive: accepts both upper- and lowercase hex + * + * Used to validate parentTraceId before propagation. traceId is always + * generated internally by crypto.randomUUID() and is guaranteed valid. + */ +const UUID_V4_REGEX = /^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; + +/** + * Returns true only when value is a canonical UUID v4 string. + * Any other value (non-string, wrong format, wrong version/variant) → false. + * + * @param {unknown} value + * @returns {boolean} + */ +function isValidParentTraceId(value) { + return typeof value === 'string' && UUID_V4_REGEX.test(value); +} + /** * Create a DispatchEvent. * @@ -25,13 +51,22 @@ const { randomUUID } = require('crypto'); * @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. + * @param {string} [opts.parentTraceId] - Must be a canonical UUID v4 (RFC 4122). + * Invalid values (non-string, wrong format, wrong version/variant) are silently coerced + * to undefined — no stderr warn is emitted. This prevents correlation poisoning from + * unvalidated caller input while keeping the factory pure and side-effect-free. * @returns {object} Immutable DispatchEvent record. */ -function makeDispatchEvent({ command, args, result, includeArgs = false, parentTraceId: _ignored }) { +function makeDispatchEvent({ command, args, result, includeArgs = false, parentTraceId }) { + // Validate parentTraceId against UUID v4 format before propagation. + // Invalid inputs (empty string, non-UUID, UUID v1, oversized, etc.) are silently + // coerced to undefined. Silent coercion keeps the factory pure — no side effects, + // no log spam on bad input, consistent with how non-string values already collapse. + const resolvedParentTraceId = isValidParentTraceId(parentTraceId) ? parentTraceId : undefined; + const event = { traceId: randomUUID(), - parentTraceId: undefined, + parentTraceId: resolvedParentTraceId, command: String(command), result, timestamp: new Date().toISOString(), diff --git a/tests/dispatch/trace-correlation.test.cjs b/tests/dispatch/trace-correlation.test.cjs new file mode 100644 index 000000000..293d3cf8c --- /dev/null +++ b/tests/dispatch/trace-correlation.test.cjs @@ -0,0 +1,227 @@ +'use strict'; + +/** + * End-to-end trace correlation tests (issue #178). + * + * Demonstrates the full parentTraceId propagation seam: + * 1. A Hub is created with a real DispatchLogger writing to a real temp audit file. + * 2. A "root" dispatch produces a root event (parentTraceId === undefined). + * 3. Three "child" dispatches pass parentTraceId = root.traceId. + * 4. The audit file is read back and all four events are verified. + * 5. A JS filter (simulating jq) confirms the three children are recoverable + * by filtering on parentTraceId === rootTraceId. + * + * No mocks. No fs stubs. Real file I/O to os.tmpdir(). + */ + +const { describe, test, before, after } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); +const os = require('os'); + +const { createHub } = require('../../get-shit-done/bin/lib/command-routing-hub.cjs'); +const { createDefaultLogger } = require('../../get-shit-done/bin/lib/observability/logger.cjs'); + +// ─── Test fixture setup ─────────────────────────────────────────────────────── + +/** Minimal registry that always succeeds — all we care about is the event shape. */ +function makeRegistry() { + return { + plan: { '': () => ({ ok: true, data: 'plan-ok' }) }, + discuss: { '': () => ({ ok: true, data: 'discuss-ok' }) }, + test: { '': () => ({ ok: true, data: 'test-ok' }) }, + }; +} + +function makeManifest() { + return { + plan: [''], + discuss: [''], + test: [''], + }; +} + +/** Parse a JSONL file into an array of parsed event objects. */ +function readJsonl(filePath) { + const raw = fs.readFileSync(filePath, 'utf8').trim(); + if (!raw) return []; + return raw.split('\n').map(line => JSON.parse(line)); +} + +// ─── Shared state for the test group ───────────────────────────────────────── + +let tmpDir; +let auditPath; +let savedAudit; +let capturedEvents; + +describe('trace correlation — end-to-end parentTraceId propagation', () => { + before(() => { + // Create an isolated temp dir for this test group + tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'gsd-trace-correlation-test-')); + auditPath = path.join(tmpDir, '.planning', '.gsd-trace.jsonl'); + + // Enable audit file writes + savedAudit = process.env.GSD_AUDIT; + process.env.GSD_AUDIT = '1'; + + // Build a Hub backed by the real logger writing to our temp dir + const logger = createDefaultLogger({ cwd: tmpDir }); + const hub = createHub({ + cjsRegistry: makeRegistry(), + manifest: makeManifest(), + logger, + }); + + // ── Root dispatch (no parentTraceId) ────────────────────────────────────── + hub.dispatch({ family: 'plan', subcommand: '' }); + + // ── Read root traceId from the audit file ───────────────────────────────── + const rootEvents = readJsonl(auditPath); + assert.equal(rootEvents.length, 1, 'setup: one event after root dispatch'); + const rootTraceId = rootEvents[0].traceId; + + // ── Child dispatches — each passes parentTraceId = rootTraceId ──────────── + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: rootTraceId }); + hub.dispatch({ family: 'discuss', subcommand: '', parentTraceId: rootTraceId }); + hub.dispatch({ family: 'test', subcommand: '', parentTraceId: rootTraceId }); + + // Capture all events for the assertions below + capturedEvents = readJsonl(auditPath); + }); + + after(() => { + // Restore GSD_AUDIT to whatever it was before this test group + if (savedAudit === undefined) { + delete process.env.GSD_AUDIT; + } else { + process.env.GSD_AUDIT = savedAudit; + } + // Clean up the temp directory + fs.rmSync(tmpDir, { recursive: true, force: true }); + }); + + // ── Assertions ──────────────────────────────────────────────────────────── + + test('audit file contains exactly 4 events (1 root + 3 children)', () => { + assert.equal(capturedEvents.length, 4, + 'audit file must contain exactly 4 events'); + }); + + test('root event has parentTraceId === undefined', () => { + const root = capturedEvents[0]; + // When parentTraceId is undefined it is omitted from JSON serialization. + // Either absent or explicitly undefined → the contract is "no parent". + const hasNoParent = !('parentTraceId' in root) || root.parentTraceId === undefined || root.parentTraceId === null; + assert.ok(hasNoParent, + `root event must have no parentTraceId, got: ${root.parentTraceId}`); + }); + + test('all 3 child events carry parentTraceId === rootTraceId', () => { + const rootTraceId = capturedEvents[0].traceId; + const children = capturedEvents.slice(1); + assert.equal(children.length, 3, 'there must be exactly 3 child events'); + for (const child of children) { + assert.strictEqual(child.parentTraceId, rootTraceId, + `child event must carry parentTraceId=${rootTraceId}, got: ${child.parentTraceId}`); + } + }); + + test('all 4 events have unique traceIds', () => { + const ids = capturedEvents.map(e => e.traceId); + const unique = new Set(ids); + assert.equal(unique.size, 4, + 'all 4 events must have unique traceIds even when parentTraceId is shared'); + }); + + test('JS filter on parentTraceId returns exactly the 3 children (jq-style)', () => { + const rootTraceId = capturedEvents[0].traceId; + // Simulates: jq 'select(.parentTraceId == $rootTraceId)' .gsd-trace.jsonl + const children = capturedEvents.filter(e => e.parentTraceId === rootTraceId); + assert.equal(children.length, 3, + 'filtering events by parentTraceId === rootTraceId must yield exactly 3 events'); + // Confirm the root itself is not in the filtered set + const rootInChildren = children.some(e => e.traceId === rootTraceId); + assert.ok(!rootInChildren, + 'the root event must not appear in the children filter result'); + }); + + test('invalid parentTraceId in a child dispatch breaks the correlation tree for that child but does not poison sibling traces', () => { + // This test uses its own isolated Hub + audit file to avoid interfering with + // the shared capturedEvents fixture above. + const isolatedTmp = fs.mkdtempSync(path.join(os.tmpdir(), 'gsd-poison-test-')); + let isolatedSavedAudit; + try { + isolatedSavedAudit = process.env.GSD_AUDIT; + process.env.GSD_AUDIT = '1'; + + const logger = createDefaultLogger({ cwd: isolatedTmp }); + const hub = createHub({ + cjsRegistry: makeRegistry(), + manifest: makeManifest(), + logger, + }); + + // Root dispatch — no parentTraceId + hub.dispatch({ family: 'plan', subcommand: '' }); + + const isolatedAuditPath = path.join(isolatedTmp, '.planning', '.gsd-trace.jsonl'); + const afterRoot = readJsonl(isolatedAuditPath); + assert.equal(afterRoot.length, 1, 'setup: one root event'); + const rootTraceId = afterRoot[0].traceId; + + // Valid child: passes rootTraceId as parentTraceId + hub.dispatch({ family: 'discuss', subcommand: '', parentTraceId: rootTraceId }); + + // Invalid child: passes 'junk' as parentTraceId + hub.dispatch({ family: 'test', subcommand: '', parentTraceId: 'junk' }); + + const allEvents = readJsonl(isolatedAuditPath); + assert.equal(allEvents.length, 3, 'must have 3 events total (root + valid child + invalid child)'); + + const [root, validChild, invalidChild] = allEvents; + + // Valid child carries the correct parentTraceId + assert.strictEqual(validChild.parentTraceId, rootTraceId, + 'valid child must carry parentTraceId === rootTraceId'); + + // Invalid child has parentTraceId coerced to undefined (absent from JSON) + const invalidChildHasNoParent = + !('parentTraceId' in invalidChild) || + invalidChild.parentTraceId === undefined || + invalidChild.parentTraceId === null; + assert.ok(invalidChildHasNoParent, + 'invalid child must have parentTraceId dropped to undefined — not "junk"'); + + // Sibling relations are unaffected: filtering by rootTraceId yields only the valid child + const correlatedChildren = allEvents.filter(e => e.parentTraceId === rootTraceId); + assert.equal(correlatedChildren.length, 1, + 'only the valid child must appear when filtering by rootTraceId — invalid child must not contaminate'); + assert.strictEqual(correlatedChildren[0].traceId, validChild.traceId, + 'the correlated child must be the valid one'); + + // All three events still have unique traceIds + const ids = allEvents.map(e => e.traceId); + assert.equal(new Set(ids).size, 3, 'all 3 events must have unique traceIds'); + } finally { + if (isolatedSavedAudit === undefined) { + delete process.env.GSD_AUDIT; + } else { + process.env.GSD_AUDIT = isolatedSavedAudit; + } + fs.rmSync(isolatedTmp, { recursive: true, force: true }); + } + }); + + test('JS filter on traceId returns only the root event', () => { + const rootTraceId = capturedEvents[0].traceId; + // Simulates: jq 'select(.traceId == $rootTraceId)' + const roots = capturedEvents.filter(e => e.traceId === rootTraceId); + assert.equal(roots.length, 1, 'filtering by traceId must return exactly one root event'); + assert.ok( + !('parentTraceId' in roots[0]) || roots[0].parentTraceId === undefined || roots[0].parentTraceId === null, + 'the root event found by traceId must have no parentTraceId' + ); + }); +}); diff --git a/tests/observability/event.test.cjs b/tests/observability/event.test.cjs index 1e9b98b76..486d521a8 100644 --- a/tests/observability/event.test.cjs +++ b/tests/observability/event.test.cjs @@ -44,14 +44,53 @@ describe('makeDispatchEvent — shape', () => { assert.notEqual(a.traceId, b.traceId, 'consecutive calls must produce different traceIds'); }); - test('parentTraceId is always undefined in P1.3', () => { + test('parentTraceId is undefined when not provided (default, backward-compat with 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'); + // P1.4: when no parentTraceId supplied, field is still undefined + assert.strictEqual(event.parentTraceId, undefined, 'parentTraceId must be undefined when not provided'); + }); + + test('parentTraceId propagates when provided as a string (P1.4)', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: 'aaaaaaaa-bbbb-4ccc-8ddd-eeeeeeeeeeee', + }); + assert.strictEqual(event.parentTraceId, 'aaaaaaaa-bbbb-4ccc-8ddd-eeeeeeeeeeee', + 'parentTraceId must be propagated when provided as a string'); + }); + + test('parentTraceId is undefined when null is passed (defensive normalization)', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: null, + }); + assert.strictEqual(event.parentTraceId, undefined, + 'null parentTraceId must be normalised to undefined'); + }); + + test('non-string parentTraceId is set to undefined for defensive safety', () => { + // Style choice: surrounding code uses undefined for absent/invalid optional fields + // (e.g. args is omitted rather than coerced). Consistent policy: non-string → undefined. + const eventNum = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: 42, + }); + assert.strictEqual(eventNum.parentTraceId, undefined, + 'number parentTraceId must be normalised to undefined'); + + const eventObj = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: { id: 'x' }, + }); + assert.strictEqual(eventObj.parentTraceId, undefined, + 'object parentTraceId must be normalised to undefined'); }); test('command is set from input', () => { @@ -116,6 +155,107 @@ describe('makeDispatchEvent — args field', () => { }); }); +describe('makeDispatchEvent — parentTraceId UUID v4 validation', () => { + const { randomUUID } = require('crypto'); + + test('invalid empty string parentTraceId is dropped to undefined', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: '', + }); + assert.strictEqual(event.parentTraceId, undefined, + 'empty string parentTraceId must be coerced to undefined'); + }); + + test('invalid whitespace-only parentTraceId is dropped to undefined', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: ' ', + }); + assert.strictEqual(event.parentTraceId, undefined, + 'whitespace-only parentTraceId must be coerced to undefined'); + }); + + test('invalid non-UUID string parentTraceId is dropped to undefined', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: 'junk', + }); + assert.strictEqual(event.parentTraceId, undefined, + '"junk" parentTraceId must be coerced to undefined'); + }); + + test('invalid oversized string parentTraceId is dropped to undefined', () => { + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: 'a'.repeat(10000), + }); + assert.strictEqual(event.parentTraceId, undefined, + '10000-char string parentTraceId must be coerced to undefined'); + }); + + test('invalid UUID v1 parentTraceId is dropped to undefined', () => { + // Version nibble is 1, not 4 — rejected by UUID v4 regex + const uuidV1Like = 'aaaaaaaa-bbbb-1ccc-8ddd-eeeeeeeeeeee'; + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: uuidV1Like, + }); + assert.strictEqual(event.parentTraceId, undefined, + 'UUID v1 parentTraceId must be dropped to undefined'); + }); + + test('invalid UUID v4 missing hyphens parentTraceId is dropped to undefined', () => { + // 32 hex chars, no hyphens + const noHyphens = '1234567812345678123456781234567812'; + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: noHyphens, + }); + assert.strictEqual(event.parentTraceId, undefined, + 'UUID v4 missing hyphens must be coerced to undefined'); + }); + + test('invalid UUID v4 with extra chars parentTraceId is dropped to undefined', () => { + const withExtra = randomUUID() + 'x'; + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: withExtra, + }); + assert.strictEqual(event.parentTraceId, undefined, + 'UUID v4 with trailing extra char must be coerced to undefined'); + }); + + test('valid UPPERCASE UUID v4 parentTraceId is propagated (case-insensitive)', () => { + const upperUUID = randomUUID().toUpperCase(); + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: upperUUID, + }); + assert.strictEqual(event.parentTraceId, upperUUID, + 'uppercase UUID v4 parentTraceId must be propagated as-is'); + }); + + test('valid lowercase UUID v4 parentTraceId is propagated', () => { + const lowerUUID = randomUUID(); // crypto.randomUUID() is always lowercase + const event = makeDispatchEvent({ + command: 'plan', + result: { kind: 'ok', data: null }, + parentTraceId: lowerUUID, + }); + assert.strictEqual(event.parentTraceId, lowerUUID, + 'lowercase UUID v4 parentTraceId must be propagated'); + }); +}); + describe('makeDispatchEvent — result variants', () => { test('ok result shape', () => { const event = makeDispatchEvent({ diff --git a/tests/observability/hub-logger-integration.test.cjs b/tests/observability/hub-logger-integration.test.cjs index 9e2164440..6168af902 100644 --- a/tests/observability/hub-logger-integration.test.cjs +++ b/tests/observability/hub-logger-integration.test.cjs @@ -179,12 +179,89 @@ describe('Hub + logger — event shape', () => { ); }); - test('event.parentTraceId is undefined in P1.3', () => { + test('event.parentTraceId is undefined when req omits parentTraceId (backward-compat with 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'); + 'parentTraceId must be undefined when req does not include it'); + }); + + test('dispatch passes req.parentTraceId through to the emitted event', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + const parentId = 'ffffffff-0000-4000-8000-aaaaaaaaaaaa'; + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: parentId }); + assert.strictEqual(tracking.calls[0].parentTraceId, parentId, + 'parentTraceId must be present on the event when passed via req'); + }); + + test('multiple dispatches with the same parentTraceId all carry that parentTraceId on their events', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + const sharedParentId = 'cccccccc-0000-4000-8000-111111111111'; + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: sharedParentId }); + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: sharedParentId }); + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: sharedParentId }); + for (const event of tracking.calls) { + assert.strictEqual(event.parentTraceId, sharedParentId, + 'every child dispatch must carry the shared parentTraceId'); + } + }); + + test('each dispatch still gets a unique traceId even when parentTraceId is shared (correlation tree invariant)', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + const sharedParentId = 'dddddddd-0000-4000-8000-222222222222'; + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: sharedParentId }); + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: sharedParentId }); + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: sharedParentId }); + const traceIds = tracking.calls.map(e => e.traceId); + const unique = new Set(traceIds); + assert.equal(unique.size, 3, + 'each dispatch must produce a unique traceId even when parentTraceId is shared'); + }); +}); + +// ─── Invalid parentTraceId silently dropped at the Hub seam ───────────────── + +describe('Hub + logger — invalid parentTraceId handling', () => { + test('dispatch with invalid parentTraceId still emits event with parentTraceId: undefined', () => { + const tracking = makeTrackingLogger(); + const hub = makeHub(tracking); + + // Send an invalid parentTraceId — not a UUID v4 + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: 'junk' }); + + assert.equal(tracking.calls.length, 1, 'onEvent must still be called once'); + const event = tracking.calls[0]; + // Factory must coerce invalid parentTraceId to undefined — logger never sees the bad value + assert.strictEqual(event.parentTraceId, undefined, + 'event.parentTraceId must be undefined when an invalid value was passed'); + }); + + test('dispatch with invalid parentTraceId does NOT trigger the logger-failure warn path', () => { + // The _notifyLogger warn path fires only when logger.onEvent throws. + // Silent coercion in the factory means the invalid parentTraceId never reaches + // the logger — so the throwing/warn code path must stay dormant. + const stderrOutput = captureStderr(() => { + const throwingLogger = { + // This logger would throw if it ever saw a non-UUID parentTraceId value, but it + // must never be reached — the factory drops it before calling the logger. + onEvent(event) { + if (event.parentTraceId !== undefined) { + throw new Error('factory passed invalid parentTraceId to logger'); + } + }, + }; + const hub = makeHub(throwingLogger); + hub.dispatch({ family: 'plan', subcommand: '', parentTraceId: '' }); + }); + + // If the logger had thrown, the Hub would have emitted a level:warn to stderr. + // Empty stderr confirms the factory silently dropped the bad value before calling onEvent. + assert.equal(stderrOutput, '', + 'no stderr warn must appear — factory coerces invalid parentTraceId without involving logger'); }); });