[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.
Merge feature/dc-055-journald-viewer: host journald log viewer
2026-08-18 01:59:14 -07:00 · 2026-08-18 01:29:45 -07:00
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/);
  });
 });
@@ -112,12 +112,78 @@ async function appendErrorLog(line) {
  }
 }
 // Flatten an error chain into readable lines so error.log records why a
 // request failed, not just that it did. Handle AggregateError (`.errors[]`,
 // common from lookups/DNS-fetch timeouts) and the modern `.cause` chain —
 // both common in Node 18+ networking. Always returns at least one line
 // (a head line with `name [code]: message`), and appends cause lines for
 // any `.errors` / `.cause` chains present.
 //
 // Defensive against:
 //  - Circular `.cause` references (a pathological error payload pointing
 //    `err.cause = err` would otherwise infinite-recurse and crash the
 //    error-path). Visited set carries forward via parameter.
 //  - Excessively deep chains (> MAX_CHAIN_DEPTH): truncated with a marker
 //    so the operator can see something IS coming from underneath.
 const MAX_CHAIN_DEPTH = 16;
 function describeErrorChain(err, depth = 0, seen = new WeakSet()) {
  const out = [];
  if (depth > MAX_CHAIN_DEPTH) {
    out.push(`${'  '.repeat(depth)}  ... (chain truncated at depth ${MAX_CHAIN_DEPTH})`);
    return out;
  }
  if (!(err instanceof Error)) {
    out.push(`${'  '.repeat(depth)}${String(err)}`);
    return out;
  }
  // Cycle guard — same Error instance already on the chain.
  if (seen.has(err)) {
    out.push(`${'  '.repeat(depth)}  ... (cycle: same Error instance seen earlier)`);
    return out;
  }
  seen.add(err);
  const indent = '  '.repeat(depth);
  const code = err.code ? ` [${err.code}]` : '';
  const msg = err.message ? `: ${err.message}` : '';
  // For every error (including AggregateError), render the head line; an
  // empty `.message` simply produces `Name [code]:` which is still useful.
  out.push(`${indent}${err.name || 'Error'}${code}${msg}`);
  if (Array.isArray(err.errors) && err.errors.length) {
    err.errors.forEach((sub, i) => {
      out.push(`${indent}  cause #${i + 1}:`);
      out.push(...describeErrorChain(sub, depth + 2, seen));
    });
  }
  if (err.cause instanceof Error) {
    out.push(`${indent}  cause:`);
    out.push(...describeErrorChain(err.cause, depth + 2, seen));
  }
  return out;
 }
 async function writeErrorLog(ctx, error, req, extra) {
  const ts = new Date().toISOString();
  const errMsg = error instanceof Error ? error.message : String(error);
  const errStack = error instanceof Error ? error.stack : '';
-  const parts = [`[${ts}] [ERR] ${ctx}: ${errMsg}`];
+  // Build the head line AND a tail diagnostic from the same describeErrorChain,
  // so plain errors with .code get `[CODE]` formatted into the head (regression)
  // and AggregateError with empty `.message` gets a diagnostic block listing
  // every cause (the actual bug fix).
  let headLine;
  let diagLines = [];
  if (error instanceof Error) {
    const chain = describeErrorChain(error);
    // The chain head is always the error itself (now including AggregateError),
    // so chain[0] is what we want in the headline and chain[1..] is the rest.
    headLine = chain[0] || `${error.name || 'Error'}`;
    diagLines = chain.slice(1);
  } else {
    headLine = String(error);
  }
  // Preserve the historical `ctx: <head>` shape so log scrapers don't break.
  // The head now carries `name [code]: message` instead of bare `.message`.
  const parts = [`[${ts}] [ERR] ${ctx}: ${headLine.replace(/^\s+/, '')}`];
  if (errStack) parts.push(errStack);
  if (diagLines.length) parts.push('  diagnostic: ' + diagLines.join('\n  diagnostic: '));
  if (req) {
    const ip = req.ip || req.socket?.remoteAddress || '';
    const ua = req.get ? req.get('user-agent') : '';