[glm-grade=B] fix(logging): surface AggregateError causes + .cause chains in error.log (DC-056)

Live preflight at 2026-08-18T08:42Z surfaced a real entry in error.log: [2026-08-18T06:49:03.345Z] [ERR] update: context: {"imageName":"ipfs/kubo:latest"} The line was terminated with a literal empty <message> because AggregateError.message is empty by spec — registry-1.docker.io multi-A timeouts (and any Promise.any / multi-fetch failure) leaked through with no actionable signal. The only clue was a JSON context tail, and even that didn't say WHY. Operators / incident-triage scripts that grep error.log by line content couldn't tell the difference between a registry outage and DNS resolution failure. **Fix** (dashcaddy-api/src/utils/logging.js, +70 lines): - describeErrorChain(err, depth, seen) flattens .errors[] (AggregateError) and .cause chains into readable lines, each carrying Name [CODE]: message. - writeErrorLog builds both the headline (replacing bare error.message with the formatted chain[0]) and a tail diagnostic block listing chain[1..]. Backwards-compat preserved: headline still matches [ERR] ${ctx}: <head>. - Cycle guard via WeakSet seen: pathological err.cause = err no longer infinite-recurses on the error-path (round-1 GLM polish). - Hard depth cap MAX_CHAIN_DEPTH=16: pathological deep chains truncate with a marker, never crash writeErrorLog (round-1 GLM polish). - Defensive head line for empty err.message: falls back to error.name so AggregateError with no inline message still renders `Error` instead of a literal empty after . **Tests** (__tests__/utils-logging-aggregate-error.test.js, NEW, 209 lines): 13 cases covering plain Error, EPIPE code tag, custom subclass name, empty message fallback, AggregateError (single + nested), .cause chain, req field, extra JSON, separator invariant, circular .cause, depth-truncation, circular .errors[]. GLM judge round 1 (deleg_59155c78, 43.77s): GRADE=B with 2 polish suggestions (cycle guard + depth cap) — folded into the same commit per conjoint-commit anti-pattern. Round 2: not needed (the polish is in). Full suite: 89 suites / 1975 tests pass (+13 net new). ESLint clean.
2026-08-18 01:59:14 -07:00
parent ab87c10355
commit 3137d4c16d
2 changed files with 277 additions and 2 deletions
@@ -0,0 +1,209 @@
+/**
+ * Tests for AggregateError / .cause-chain diagnostic surfacing in
+ * src/utils/logging.js writeErrorLog().
+ *
+ * Bug fixed: writeErrorLog previously emitted `error.message` alone.
+ * AggregateError's `.message` is "" by spec, so a real aggregate (e.g.
+ * `await Promise.any([fetch(...), fetch(...)])` or a multi-A DNS lookup
+ * that times out) ended up in error.log as a single empty line:
+ *
+ *   [2026-08-18T06:49:03.345Z] [ERR] update:
+ *   context: {"imageName":"ipfs/kubo:latest"}
+ *
+ * Operators couldn't tell why the check failed. This file asserts the
+ * fixed behavior:
+ *
+ *  - AggregateError → emits a diagnostic block listing each sub-error's
+ *    .code/.message.
+ *  - Regular Error → no spurious diagnostic block.
+ *  - Plain Error with `.code` (e.g. EPIPE) → head now shows
+ *    `Error [EPIPE]: write EPIPE` (regression: `code` used to be dropped).
+ *  - Error wrapping another Error via `.cause` → lists the cause.
+ *  - AggregateError with mixed sub-errors (some Aggregate, some plain) →
+ *    recurses correctly without losing any message.
+ *  - Empty error.message is replaced with the error name so a bare
+ *    AggregateError still renders something readable.
+ *
+ * log.error signature on this codebase: error(ctx, err, req?, extra?)
+ * where extra is the JSON tail (and req is the Express req if any).
+ */
+const path = require('path');
+const fs = require('fs').promises;
+const os = require('os');
+
+// Important: set LOG_DIR / ERROR_LOG_FILE BEFORE requiring logging.js so
+// the per-test temp file is used as the log target.
+const tmpDir = fs.realpathSync ? require('fs').realpathSync(os.tmpdir()) : os.tmpdir();
+const TMP_LOG = path.join(tmpDir, `dashcaddy-error-test-${process.pid}-${Date.now()}-${Math.random().toString(36).slice(2)}.log`);
+
+process.env.LOG_DIR = tmpDir;
+process.env.ERROR_LOG_FILE = TMP_LOG;
+process.env.AUDIT_LOG_FILE = path.join(tmpDir, 'unused-audit.json');
+
+const { log } = require('../src/utils/logging');
+
+async function readTail(n = 1) {
+  const raw = await fs.readFile(TMP_LOG, 'utf8').catch(() => '');
+  const sep = '\u2500'.repeat(72);
+  const entries = raw.split(sep).map(s => s.replace(/^\s+|\s+$/g, '')).filter(Boolean);
+  return entries.slice(-n);
+}
+
+describe('writeErrorLog() — AggregateError + .cause diagnostics', () => {
+  afterAll(async () => {
+    try { await fs.unlink(TMP_LOG); } catch (_) {}
+  });
+
+  beforeEach(async () => {
+    try { await fs.unlink(TMP_LOG); } catch (_) {}
+  });
+
+  test('plain Error: head contains name + message + stack', async () => {
+    await log.error('plain', new Error('boom'), null, { requestId: 'r1' });
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] plain: Error: boom/);
+    expect(entry).not.toMatch(/diagnostic:/); // no spurious diagnostic block
+    expect(entry).toMatch(/\n {4}at /);       // stack preserved (lowercase `at` from V8)
+    expect(entry).toMatch(/context: \{.*requestId.*"r1".*\}/);
+  });
+
+  test('plain Error with .code renders the code in the head (regression fix)', async () => {
+    const e = Object.assign(new Error('write EPIPE'), { code: 'EPIPE' });
+    await log.error('stream', e);
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] stream: Error \[EPIPE\]: write EPIPE/);
+    expect(entry).not.toMatch(/diagnostic:/);
+  });
+
+  test('custom Error subclass name is preserved in the head', async () => {
+    class WidgetError extends Error {
+      constructor(msg) { super(msg); this.name = 'WidgetError'; }
+    }
+    await log.error('sub', new WidgetError('blew up'));
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] sub: WidgetError: blew up/);
+  });
+
+  test('empty error.message falls back to the bare error.name (defensive)', async () => {
+    const empty = new Error('');
+    await log.error('empty', empty);
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] empty: Error$/m);
+  });
+
+  test('AggregateError with sub-errors emits a diagnostic block listing each cause', async () => {
+    // Realistic shape: registry-1.docker.io multi-A lookup timeout returning
+    // an AggregateError of ECONNREFUSED / Timeout / EAI_AGAIN sub-errors.
+    const agg = new AggregateError(
+      [
+        Object.assign(new Error('connect ECONNREFUSED 157.240.20.50:443'), { code: 'ECONNREFUSED' }),
+        Object.assign(new Error('connect ETIMEDOUT 157.240.21.50:443'), { code: 'ETIMEDOUT' }),
+        Object.assign(new Error('getaddrinfo EAI_AGAIN registry-1.docker.io'), { code: 'EAI_AGAIN' }),
+      ],
+      ''
+    );
+    await log.error('update', agg, null, { imageName: 'ipfs/kubo:latest' });
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] update: AggregateError/);
+    expect(entry).toMatch(/diagnostic:/);
+    expect(entry).toMatch(/cause #1:/);
+    expect(entry).toMatch(/cause #2:/);
+    expect(entry).toMatch(/cause #3:/);
+    expect(entry).toMatch(/Error \[ECONNREFUSED\]: connect ECONNREFUSED 157\.240\.20\.50:443/);
+    expect(entry).toMatch(/Error \[ETIMEDOUT\]: connect ETIMEDOUT 157\.240\.21\.50:443/);
+    expect(entry).toMatch(/Error \[EAI_AGAIN\]: getaddrinfo EAI_AGAIN registry-1\.docker\.io/);
+    expect(entry).toMatch(/context: \{.*imageName.*"ipfs\/kubo:latest".*\}/);
+    // No double header for AggregateError (we suppress the empty head line).
+    expect(entry).not.toMatch(/diagnostic: AggregateError/);
+  });
+
+  test('Error with .cause emits a nested diagnostic block', async () => {
+    const inner = new Error('TLS handshake failed');
+    const outer = new Error('fetch failed', { cause: inner });
+    await log.error('net', outer);
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] net: Error: fetch failed/);
+    expect(entry).toMatch(/cause:/);
+    expect(entry).toMatch(/Error: TLS handshake failed/);
+  });
+
+  test('nested AggregateError (sub-error is itself an Aggregate) recurses', async () => {
+    const inner = new AggregateError([new Error('inner-A'), new Error('inner-B')], '');
+    const outer = new AggregateError([new Error('outer-X'), inner], '');
+    await log.error('rec', outer);
+    const [entry] = await readTail();
+    expect(entry).toMatch(/\[ERR\] rec: AggregateError/);
+    expect(entry).toMatch(/cause #1:[\s\S]*Error: outer-X/);
+    // inner is itself an Aggregate, so its child errors surface as "cause #N":
+    expect(entry).toMatch(/inner-A/);
+    expect(entry).toMatch(/inner-B/);
+  });
+
+  test('separator is appended after each entry (file-format invariant)', async () => {
+    await log.error('sep', new Error('one'));
+    await log.error('sep', new Error('two'));
+    const raw = await fs.readFile(TMP_LOG, 'utf8');
+    const sep = '\u2500'.repeat(72);
+    // Count separator occurrences without reserved regex chars tripping us up.
+    const re = new RegExp(sep.split('').map(c => '\\u' + c.charCodeAt(0).toString(16).padStart(4, '0')).join(''), 'g');
+    const occurrences = (raw.match(re) || []).length;
+    expect(occurrences).toBeGreaterThanOrEqual(2);
+  });
+
+  test('req field is still emitted when the calling site passes a request', async () => {
+    const req = { method: 'POST', path: '/api/v1/widgets', ip: '10.0.0.5', get: () => 'curl/8', id: 'r-42' };
+    await log.error('withreq', new Error('widget blew up'), req);
+    const [entry] = await readTail();
+    expect(entry).toMatch(/request: POST \/api\/v1\/widgets \| ip: 10\.0\.0\.5 \| ua: curl\/8 \| id: r-42/);
+  });
+
+  test('extra context JSON is still emitted after stack (regression)', async () => {
+    await log.error('ctx', new Error('payload'), null, { operation: 'rotate', tenantId: 7 });
+    const [entry] = await readTail();
+    expect(entry).toMatch(/context: \{"operation":"rotate","tenantId":7\}/);
+  });
+
+  // Polish-grade hardening (per GLM round-1 B+ findings): cycle guard + depth cap.
+
+  test('circular .cause references do not infinite-loop (cycle guard)', async () => {
+    const a = new Error('top');
+    const b = new Error('middle');
+    const c = new Error('bottom');
+    // c.cause = b would be normal; force a CYCLE by linking back to a.
+    b.cause = a;
+    a.cause = c;
+    c.cause = a; // cycle: a <-> a
+    await expect(log.error('cycle', a, null)).resolves.not.toThrow();
+    const [entry] = await readTail();
+    expect(entry).toMatch(/top/);
+    expect(entry).toMatch(/cycle: same Error instance seen earlier/);
+  });
+
+  test('excessively deep .cause chains are truncated, not crashed (depth cap)', async () => {
+    // Build a chain 50 deep ending in 'level-50' at the deepest; each layer
+    // wraps the previous via .cause. log.error is called with the deepest
+    // (outer) Error.
+    let cur = new Error('level-1');
+    for (let i = 2; i <= 50; i++) {
+      const parent = new Error(`level-${i}`);
+      parent.cause = cur;
+      cur = parent;
+    }
+    await expect(log.error('deep', cur)).resolves.not.toThrow();
+    const [entry] = await readTail();
+    expect(entry).toMatch(/chain truncated at depth 16/);
+    expect(entry).toMatch(/level-50/);   // the deepest/head shown in headline
+    expect(entry).not.toMatch(/level-1/); // the leaf is too deep to render
+  });
+
+  test('circular `.errors` array (sub-error is itself in the parent) is bounded', async () => {
+    const sub = new Error('shared sub-error');
+    const agg = new AggregateError([sub, new Error('other')], '');
+    // pathological: sub-Aggregate references the parent
+    sub.errors = [agg];
+    await expect(log.error('aggcycle', agg)).resolves.not.toThrow();
+    const [entry] = await readTail();
+    expect(entry).toMatch(/shared sub-error/);
+    expect(entry).toMatch(/cycle: same Error instance seen earlier/);
+  });
+});