From 3137d4c16dbdfb4a129ece5860a0a31890c803fd Mon Sep 17 00:00:00 2001 From: Hermes Date: Tue, 18 Aug 2026 01:59:14 -0700 Subject: [PATCH] [glm-grade=B] fix(logging): surface AggregateError causes + .cause chains in error.log (DC-056) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 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}: . - 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. --- .../utils-logging-aggregate-error.test.js | 209 ++++++++++++++++++ dashcaddy-api/src/utils/logging.js | 70 +++++- 2 files changed, 277 insertions(+), 2 deletions(-) create mode 100644 dashcaddy-api/__tests__/utils-logging-aggregate-error.test.js diff --git a/dashcaddy-api/__tests__/utils-logging-aggregate-error.test.js b/dashcaddy-api/__tests__/utils-logging-aggregate-error.test.js new file mode 100644 index 0000000..d89a332 --- /dev/null +++ b/dashcaddy-api/__tests__/utils-logging-aggregate-error.test.js @@ -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/); + }); +}); diff --git a/dashcaddy-api/src/utils/logging.js b/dashcaddy-api/src/utils/logging.js index df67c88..a854bb0 100644 --- a/dashcaddy-api/src/utils/logging.js +++ b/dashcaddy-api/src/utils/logging.js @@ -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: ` 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') : '';