From 5d764a40ee790e354dcb3ca62a3c1ff6df99f81c Mon Sep 17 00:00:00 2001 From: Marcus Bearden Date: Thu, 23 Jul 2026 09:11:11 +0100 Subject: [PATCH] fix(logs): stop the async-EPIPE log-flood loop at its ignition point (#8207) * fix(logs): stop an async EPIPE becoming an uncaughtException loop A raw process.stderr.write into a broken pipe fails asynchronously, so the try/catch around it never sees the failure. The stream emits 'error'; with no listener on process.stderr Node re-throws it as an uncaughtException; the framework's handler logs that through console.error; and the patched console writes back into the same dead stream. That closes a self-sustaining loop. Attach an 'error' listener to process.stdout and process.stderr. Node only converts a stream 'error' into an uncaughtException when the emitter has no listener, so the listener alone terminates the cycle. Measured in a spawn harness over 1.5s: 3,387 uncaught exceptions before, 0 after. Absorb EPIPE only. Attaching a listener otherwise makes every stream error on those streams non-fatal process-wide, so ENOSPC, EBADF and the rest are re-raised on a fresh stack to preserve today's crash semantics. The accompanying test asserts that in a child process, because node:test attributes any in-process uncaughtException to the running test. Add a test-only reset() to undo the patched console and the listeners: test:unit:fast runs --test-isolation=none, so leaked state would reach every subsequent test file. Refs #8181 * fix(logs): bound interceptor disk writes and self-heal a missing log dir Two write-path defects in the same file, both independent of the loop itself. writeEntry appended with no rate limit, so while the loop spun it wrote unbounded lines to disk (4.3 GB in 90 minutes in the reported incident). Apply the same policy #1006 established in structuredLogger -- 50 writes/sec, a 5s dedup window, a bounded tracking map -- but scoped to `error` entries only. That scoping is deliberate: structuredLogger applies its limiter solely to error() and fatal(), whereas writeEntry serves all five of log/info/warn/error/debug across ~800 non-error call sites. Capping those would silently drop routine logging from the Console Log Viewer's file. A test asserts non-error levels stay unlimited. ensureDir() ran once in initConsoleInterceptor and never again, so a log directory removed while the process was alive made every later append throw ENOENT into a bare catch -- console file-logging then stopped permanently with nothing surfaced anywhere. Recreate the directory and retry once, and report the failure exactly once through the unpatched stderr so it cannot recurse through the patched console or become a flood of its own. Refs #8181 * fix(logs): skip raw stderr writes to a stream already known dead error() and fatal() write with a raw process.stderr.write wrapped in try {} catch {}. The comment on that line says the raw write exists to avoid Next.js console patching "that triggers EPIPE loops" -- but on a broken pipe the write fails asynchronously, so the catch never sees it, and the resulting stream error is what ignites the loop. Skip the write when the stream is already destroyed or ended, falling through to the file sink as before. The listener added earlier is what breaks the cycle; this stops the ignition point firing into a dead stream in the first place. The existing try/catch is retained for the synchronous cases it always covered. The #1006 suppression policy and its call sites are untouched. Refs #8181 * fix(logs): install the stdio guard independently of console interception initConsoleInterceptor() returns early when APP_LOG_TO_FILE=false, and when the log directory cannot be created. The stdio 'error' listeners were installed after that return, so in those supported configurations no listener was attached at all. structuredLogger's raw stderr writes still happen there, and an ordinary broken pipe raises an async EPIPE without destroyed or writableEnded being set first, so the guard in safeStderrWrite does not cover it either. The loop this change exists to prevent was therefore still reachable with file logging turned off. Extract installStdioErrorGuard() and call it before the early return. It is idempotent and cleared by reset(). A new test asserts, in a child process, that both listeners are present when APP_LOG_TO_FILE=false. Also restore APP_LOG_TO_FILE and APP_LOG_FILE_PATH in the test's after() hook. test:unit:fast runs with --test-isolation=none, so the previous top-level mutations leaked into later test files, leaving file logging enabled against a path this file deletes. Refs #8181 --- .../console-interceptor-epipe-log-flood.md | 1 + src/lib/consoleInterceptor.ts | 173 +++++++++++- src/shared/utils/structuredLogger.ts | 44 ++- .../unit/lib/consoleInterceptor-epipe.test.ts | 263 ++++++++++++++++++ .../lib/consoleInterceptor-writes.test.ts | 172 ++++++++++++ .../structuredLogger-raw-write-guard.test.ts | 107 +++++++ 6 files changed, 752 insertions(+), 8 deletions(-) create mode 100644 changelog.d/fixes/console-interceptor-epipe-log-flood.md create mode 100644 tests/unit/lib/consoleInterceptor-epipe.test.ts create mode 100644 tests/unit/lib/consoleInterceptor-writes.test.ts create mode 100644 tests/unit/shared/structuredLogger-raw-write-guard.test.ts diff --git a/changelog.d/fixes/console-interceptor-epipe-log-flood.md b/changelog.d/fixes/console-interceptor-epipe-log-flood.md new file mode 100644 index 0000000000..8fe139afc6 --- /dev/null +++ b/changelog.d/fixes/console-interceptor-epipe-log-flood.md @@ -0,0 +1 @@ +- **Logging**: a broken stdout/stderr pipe no longer drives a self-sustaining log-flood loop — `consoleInterceptor` attaches `'error'` listeners to both std streams so an async EPIPE stops becoming an `uncaughtException` the framework re-logs through the patched console (measured 3,387 uncaught exceptions in 1.5s, now 0), non-EPIPE stream errors are re-raised so conditions like `ENOSPC` stay fatal, `structuredLogger`'s raw stderr writes skip a stream already known dead, interceptor disk writes are rate limited at `error` level only so ordinary logging is untouched, and a log directory removed at runtime is recreated instead of silently ending file logging (#8181) diff --git a/src/lib/consoleInterceptor.ts b/src/lib/consoleInterceptor.ts index c5c47df528..19e245217e 100644 --- a/src/lib/consoleInterceptor.ts +++ b/src/lib/consoleInterceptor.ts @@ -21,6 +21,55 @@ declare global { var __omnirouteConsoleInterceptorInit: boolean | undefined; } +type ConsoleMethod = (...args: unknown[]) => void; + +/** + * State owned by initConsoleInterceptor, cleared by __consoleInterceptorInternals.reset(). + * Kept module-level (not inside init) so reset() can undo a previous init: `test:unit:fast` + * runs with `--test-isolation=none`, so a patched console or a leaked stream listener would + * otherwise persist across every subsequent test file in the process. + */ +let savedConsoleMethods: Partial> | null = null; +let streamErrorHandler: ((err: unknown) => void) | null = null; + +function isEpipe(error: unknown): boolean { + return (error as NodeJS.ErrnoException | null)?.code === "EPIPE"; +} + +/** + * Handle an 'error' event on process.stdout / process.stderr. + * + * Node only converts a stream 'error' into an uncaughtException when the emitter has no + * listener, so simply attaching this handler is what breaks the #8181 loop. + * + * That also means attaching it absorbs EVERY stream error on these streams, process-wide — + * including conditions that are fatal today (ENOSPC, EBADF, ECONNRESET). Absorb EPIPE, which + * is the one we are here to survive, and re-raise everything else on a fresh stack so the + * process keeps its current crash semantics. + */ +function handleStreamError(error: unknown): void { + if (isEpipe(error)) return; + setImmediate(() => { + throw error; + }); +} + +/** + * Install the stdio error guard. Idempotent. + * + * Deliberately independent of console interception. `structuredLogger.error()`/`.fatal()` + * write to stderr directly, and those writes happen whether or not file logging is enabled, + * so a broken pipe can raise an async EPIPE in configurations where interception is off + * (`APP_LOG_TO_FILE=false`, or a log directory that cannot be created). The guard has to be + * in place for those too, otherwise the very loop this exists to prevent is still reachable. + */ +function installStdioErrorGuard(): void { + if (streamErrorHandler) return; + streamErrorHandler = handleStreamError; + process.stdout.on("error", streamErrorHandler); + process.stderr.on("error", streamErrorHandler); +} + /** * Map console method names to log levels. */ @@ -69,19 +118,97 @@ function argsToMessage(args: unknown[]): string { .join(" "); } +// Rate limiting for interceptor disk writes, applied to `error` entries ONLY. +// +// The policy mirrors #1006's in structuredLogger (50 writes/sec, 5s dedup, bounded map) so the +// numbers are ones upstream has already accepted. The `error`-only scope is deliberate and is +// not what #1006 did by accident: structuredLogger applies its limiter solely to error() and +// fatal(), whereas writeEntry here serves all five of log/info/warn/error/debug across ~800 +// non-error call sites. Applying a 50/sec cap to ordinary logging would silently drop routine +// startup and per-request lines from the Console Log Viewer's file. +const ERROR_DEDUP_WINDOW_MS = 5_000; +const ERROR_MAX_WRITES_PER_SECOND = 50; +const ERROR_MAX_TRACKED = 500; + +let recentErrorEntries = new Map(); +let errorWriteCount = 0; +let errorWindowStart = Date.now(); +let missingDirNoticeEmitted = false; + +function shouldSuppressErrorEntry(message: string): boolean { + const now = Date.now(); + + if (now - errorWindowStart > 1000) { + errorWriteCount = 0; + errorWindowStart = now; + } + if (errorWriteCount >= ERROR_MAX_WRITES_PER_SECOND) return true; + + const firstSeen = recentErrorEntries.get(message); + if (firstSeen !== undefined && now - firstSeen < ERROR_DEDUP_WINDOW_MS) return true; + + if (recentErrorEntries.size >= ERROR_MAX_TRACKED) { + // Map preserves insertion order; evict oldest as a backstop against a unique-message burst. + const oldest = recentErrorEntries.keys().next(); + if (!oldest.done) recentErrorEntries.delete(oldest.value); + } + + recentErrorEntries.set(message, now); + errorWriteCount++; + return false; +} + +/** + * Report, exactly once, that the log file has become unwritable. + * + * Written straight to stderr rather than through console: console is patched by this module, + * so routing it there would re-enter writeEntry and could recurse. Guarded on stream health + * for the same reason structuredLogger's raw writes now are (#8181). + */ +function emitMissingDirNoticeOnce(): void { + if (missingDirNoticeEmitted) return; + missingDirNoticeEmitted = true; + if (process.stderr.destroyed || process.stderr.writableEnded) return; + try { + process.stderr.write( + `[consoleInterceptor] console file-logging is failing; log file unavailable: ${logFilePath}\n` + ); + } catch { + /* the notice is best-effort by definition */ + } +} + /** * Append a JSON log entry to the log file. + * + * ensureDir() runs once in initConsoleInterceptor(), so if the log directory is removed while + * the process is alive every subsequent append throws ENOENT into the catch below and console + * file-logging stops permanently, with nothing surfaced. Recreate the directory and retry once + * before giving up, and say so on the first failure. */ function writeEntry(level: string, args: unknown[]) { try { const message = argsToMessage(args); + if (level === "error" && shouldSuppressErrorEntry(message)) return; + const entry = { timestamp: new Date().toISOString(), level, component: extractComponent(message), message, }; - appendFileSync(logFilePath, JSON.stringify(entry) + "\n"); + const line = JSON.stringify(entry) + "\n"; + + try { + appendFileSync(logFilePath, line); + } catch { + try { + ensureDir(); + appendFileSync(logFilePath, line); + } catch { + emitMissingDirNoticeOnce(); + } + } } catch { // Silently fail — never break the app over log writing } @@ -99,6 +226,10 @@ function shouldIgnoreConsoleWriteError(error: unknown): boolean { * Safe to call multiple times — only initializes once. */ export function initConsoleInterceptor(): void { + // Install the stdio guard first, before any early return. It protects the raw stderr writes + // in structuredLogger, which happen regardless of whether console interception is enabled. + installStdioErrorGuard(); + if (!logToFile || globalThis.__omnirouteConsoleInterceptorInit) return; try { @@ -110,6 +241,18 @@ export function initConsoleInterceptor(): void { globalThis.__omnirouteConsoleInterceptorInit = true; + // Capture the raw method references first, so reset() can restore the exact functions that + // were installed before patching. The bound copies below are for calling, not restoring — + // restoring a bound copy would change function identity and defeat the save/restore that + // existing console-mocking tests rely on. + savedConsoleMethods = { + log: console.log as ConsoleMethod, + info: console.info as ConsoleMethod, + warn: console.warn as ConsoleMethod, + error: console.error as ConsoleMethod, + debug: console.debug as ConsoleMethod, + }; + // Save original methods const originalMethods = { log: console.log.bind(console), @@ -134,3 +277,31 @@ export function initConsoleInterceptor(): void { }; } } + +/** + * Test-only internals. + * + * `reset()` is not a convenience: `test:unit:fast` runs `--test-isolation=none`, so every unit + * test file shares one process. Without it, an interceptor initialised by one file would leave + * console patched and stream listeners attached for every file that follows. + */ +export const __consoleInterceptorInternals = { + reset(): void { + if (streamErrorHandler) { + process.stdout.removeListener("error", streamErrorHandler); + process.stderr.removeListener("error", streamErrorHandler); + streamErrorHandler = null; + } + if (savedConsoleMethods) { + for (const [method, fn] of Object.entries(savedConsoleMethods)) { + if (fn) (console as unknown as Record)[method] = fn; + } + savedConsoleMethods = null; + } + recentErrorEntries = new Map(); + errorWriteCount = 0; + errorWindowStart = Date.now(); + missingDirNoticeEmitted = false; + globalThis.__omnirouteConsoleInterceptorInit = undefined; + }, +}; diff --git a/src/shared/utils/structuredLogger.ts b/src/shared/utils/structuredLogger.ts index 252677a6c1..632eb8e55a 100644 --- a/src/shared/utils/structuredLogger.ts +++ b/src/shared/utils/structuredLogger.ts @@ -166,8 +166,41 @@ export const __structuredLoggerInternals = { recentErrors: _recentErrors, pruneRecentErrors, MAX_TRACKED_ERRORS, + isStreamWritable, }; +/** + * True when a stream can still accept a write. + * + * Exported via __structuredLoggerInternals for tests: the real process.stderr cannot be + * destroyed in-process to exercise this, because the test runner writes its own output there. + */ +function isStreamWritable(stream: { destroyed?: boolean; writableEnded?: boolean }): boolean { + return stream.destroyed !== true && stream.writableEnded !== true; +} + +/** + * Write a line to stderr, skipping the write entirely when the stream is already known-bad. + * + * The `try {} catch {}` this replaces could only ever catch a *synchronous* failure. On a + * broken pipe the write fails asynchronously and surfaces as an 'error' event on the stream, + * which — with no listener attached — Node re-throws as an uncaughtException. That is the + * ignition point of the #8181 log-flood loop, and it fires from the very line whose comment + * says raw stderr writes are used to *avoid* EPIPE loops. + * + * consoleInterceptor now attaches the listener that stops the loop; this guard is defence in + * depth, so a dead stream is not written to in the first place. The catch is retained for the + * synchronous cases it always covered. + */ +function safeStderrWrite(text: string): void { + if (!isStreamWritable(process.stderr)) return; + try { + process.stderr.write(text); + } catch { + /* synchronous write failures remain non-fatal, as before */ + } +} + export function createLogger(component: string) { return { debug(message: string, meta?: Record) { @@ -195,19 +228,16 @@ export function createLogger(component: string) { if (currentLevel <= LOG_LEVELS.error) { if (shouldSuppressError(message)) return; const entry = buildEntry("error", component, message, meta); - // Use stderr.write to avoid Next.js console patching that triggers EPIPE loops - try { - process.stderr.write(formatEntry("error", component, message, meta) + "\n"); - } catch {} + // Use stderr.write to avoid Next.js console patching that triggers EPIPE loops. + // Guarded: an unguarded write here is the ignition point of #8181. + safeStderrWrite(formatEntry("error", component, message, meta) + "\n"); writeToFile(entry); } }, fatal(message: string, meta?: Record) { if (shouldSuppressError(message)) return; const entry = buildEntry("fatal", component, message, meta); - try { - process.stderr.write(formatEntry("fatal", component, message, meta) + "\n"); - } catch {} + safeStderrWrite(formatEntry("fatal", component, message, meta) + "\n"); writeToFile(entry); }, child(defaultMeta: Record) { diff --git a/tests/unit/lib/consoleInterceptor-epipe.test.ts b/tests/unit/lib/consoleInterceptor-epipe.test.ts new file mode 100644 index 0000000000..4a968e3bb3 --- /dev/null +++ b/tests/unit/lib/consoleInterceptor-epipe.test.ts @@ -0,0 +1,263 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { mkdtempSync, rmSync, existsSync, writeFileSync } from "node:fs"; +import { spawnSync } from "node:child_process"; +import { fileURLToPath } from "node:url"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +// Issue #8181: a raw `process.stderr.write` into a broken pipe fails ASYNCHRONOUSLY, so the +// `try {} catch {}` around it in structuredLogger cannot catch it. The stream emits 'error'; +// because nothing listens on process.stderr, Node re-throws it as an uncaughtException; the +// framework's handler logs that via console.error; consoleInterceptor's patched console.error +// appends to disk and re-writes to the same dead stream — closing a self-sustaining loop. +// Measured in a spawn harness: 3,387 uncaughtExceptions in 1.5s, versus 0 with an 'error' +// listener attached. +// +// The listener is the whole fix, but attaching one absorbs EVERY stream error on those +// streams, converting conditions that are fatal today (ENOSPC, EBADF) into silent no-ops. +// So EPIPE is absorbed and everything else is re-raised. The ENOSPC test below is the guard +// against that regression — it is the test that a latch-state assertion would not catch. +// +// Configure file logging BEFORE importing the interceptor: consoleInterceptor.ts reads +// getAppLogToFile() at module load, and tests/_setup/isolateDataDir.ts sets +// APP_LOG_TO_FILE ||= "false", which would otherwise make initConsoleInterceptor() a no-op +// and every assertion here vacuous. Static imports hoist, so this must be a dynamic import. +const dir = mkdtempSync(join(tmpdir(), "omniroute-interceptor-8181-")); +const logFile = join(dir, "logs", "application", "app.log"); + +// Capture the prior values so test.after() can put them back. test:unit:fast runs with +// --test-isolation=none, so these top-level mutations would otherwise leak into every later +// test file in the process, leaving file logging enabled against a path this file deletes. +const prevLogToFile = process.env.APP_LOG_TO_FILE; +const prevLogFilePath = process.env.APP_LOG_FILE_PATH; + +process.env.APP_LOG_TO_FILE = "true"; +process.env.APP_LOG_FILE_PATH = logFile; + +const { initConsoleInterceptor, __consoleInterceptorInternals } = + await import("../../../src/lib/consoleInterceptor.ts"); + +function withUncaughtRecorder(): { + seen: () => unknown; + restore: () => void; +} { + let uncaught: unknown = null; + const onUncaught = (err: unknown) => { + uncaught = err; + }; + process.on("uncaughtException", onUncaught); + return { + seen: () => uncaught, + restore: () => process.removeListener("uncaughtException", onUncaught), + }; +} + +const settle = () => new Promise((r) => setTimeout(r, 50)); + +test("init attaches an 'error' listener to process.stdout and process.stderr (#8181)", () => { + __consoleInterceptorInternals.reset(); + const beforeOut = process.stdout.listenerCount("error"); + const beforeErr = process.stderr.listenerCount("error"); + + initConsoleInterceptor(); + + assert.ok( + process.stdout.listenerCount("error") > beforeOut, + "process.stdout must carry an 'error' listener — without one, an async EPIPE re-throws " + + "as an uncaughtException and closes the #8181 loop" + ); + assert.ok( + process.stderr.listenerCount("error") > beforeErr, + "process.stderr must carry an 'error' listener (#8181)" + ); +}); + +test("an EPIPE on process.stderr does not surface as an uncaughtException (#8181)", async () => { + __consoleInterceptorInternals.reset(); + initConsoleInterceptor(); + const rec = withUncaughtRecorder(); + try { + const err = Object.assign(new Error("write EPIPE"), { code: "EPIPE" }); + try { + process.stderr.emit("error", err); + } catch (syncThrow) { + assert.fail( + `EPIPE must be absorbed by the listener, not thrown synchronously: ${String(syncThrow)}` + ); + } + await settle(); + assert.equal( + rec.seen(), + null, + `an EPIPE stream error must be absorbed, not raised: ${String(rec.seen())}` + ); + } finally { + rec.restore(); + } +}); + +// NOTE: there is deliberately no "emit EPIPE on process.stdout" test here. Emitting a +// synthetic 'error' on the real process.stdout destroys node:test's own reporting — the +// runner writes its results to that stream, so every subsequent per-test line is swallowed +// and the file reports a bare failure with no diagnostic. (Verified: a 3-test probe emitting +// on stdout reported `pass 3, fail 0` but printed only the file line.) The stdout path is +// covered structurally by the listener-count assertion above; its behaviour is identical to +// stderr's because both streams share one handler. +test("the same handler is registered on both streams, so stdout behaves as stderr does", () => { + __consoleInterceptorInternals.reset(); + initConsoleInterceptor(); + + const outListeners = process.stdout.listeners("error"); + const errListeners = process.stderr.listeners("error"); + const shared = outListeners.filter((fn) => errListeners.includes(fn)); + + assert.ok( + shared.length > 0, + "process.stdout and process.stderr must share the interceptor's error handler — the " + + "stdout EPIPE path cannot be exercised directly without breaking the test reporter, so " + + "this identity check is what proves it is wired the same way" + ); +}); + +// The regression guard, and the reason it runs in a child process. +// +// Attaching an 'error' listener silently makes EVERY stream error non-fatal, process-wide — +// ENOSPC, EBADF, ECONNRESET included. A test that only asserts internal latch/handler state +// passes while shipping exactly that regression, so the assertion has to be behavioural. +// +// It cannot be asserted in-process: the re-raise surfaces as an uncaughtException, and +// node:test attributes any uncaughtException during a test to that test and fails it. So we +// assert the real guarantee — "a non-EPIPE stream error still terminates the process" — by +// measuring a child's exit code, which is the semantics callers actually depend on. +test("a non-EPIPE stream error is still fatal: it must be re-raised (#8181)", async () => { + const interceptor = fileURLToPath( + new URL("../../../src/lib/consoleInterceptor.ts", import.meta.url) + ); + const childDir = mkdtempSync(join(tmpdir(), "omniroute-interceptor-8181-child-")); + const childFile = join(childDir, "reraise-probe.mts"); + + writeFileSync( + childFile, + [ + `process.env.APP_LOG_TO_FILE = "true";`, + `process.env.APP_LOG_FILE_PATH = ${JSON.stringify(join(childDir, "logs", "application", "app.log"))};`, + `const m = await import(${JSON.stringify(interceptor)});`, + `m.initConsoleInterceptor();`, + `process.stderr.emit("error", Object.assign(new Error("disk full"), { code: "ENOSPC" }));`, + `setTimeout(() => process.exit(0), 300);`, // if the error was absorbed, we exit 0 = regression + ].join("\n") + ); + + const result = spawnSync(process.execPath, ["--import", "tsx/esm", childFile], { + encoding: "utf8", + timeout: 30_000, + env: { ...process.env, DISABLE_SQLITE_AUTO_BACKUP: "true" }, + }); + + rmSync(childDir, { recursive: true, force: true }); + + assert.notEqual( + result.status, + 0, + "a non-EPIPE stream error must still terminate the process. Exit 0 means the interceptor's " + + "'error' listener swallowed it, silently converting a condition that is fatal today into " + + "a no-op for all code in the process, not just the interceptor." + ); + assert.match( + String(result.stderr), + /ENOSPC/, + "the original error must be re-raised unchanged, preserving its code" + ); +}); + +// The stdio guard must not depend on file logging. initConsoleInterceptor() returns early when +// APP_LOG_TO_FILE=false (and when the log directory cannot be created), but structuredLogger's +// raw stderr writes still happen in those configurations, so the loop would remain reachable +// if the listeners were only installed on the interception path. +test("the stdio guard is installed even when file logging is disabled (#8181)", () => { + const probe = fileURLToPath(new URL("../../../src/lib/consoleInterceptor.ts", import.meta.url)); + const childDir = mkdtempSync(join(tmpdir(), "omniroute-interceptor-8181-nofile-")); + const childFile = join(childDir, "nofile-probe.mts"); + + writeFileSync( + childFile, + [ + `process.env.APP_LOG_TO_FILE = "false";`, // interception off + `const m = await import(${JSON.stringify(probe)});`, + `m.initConsoleInterceptor();`, + `const ok = process.stderr.listenerCount("error") > 0 && process.stdout.listenerCount("error") > 0;`, + `process.exit(ok ? 0 : 7);`, + ].join("\n") + ); + + const result = spawnSync(process.execPath, ["--import", "tsx/esm", childFile], { + encoding: "utf8", + timeout: 30_000, + env: { ...process.env, DISABLE_SQLITE_AUTO_BACKUP: "true", APP_LOG_TO_FILE: "false" }, + }); + + rmSync(childDir, { recursive: true, force: true }); + + assert.equal( + result.status, + 0, + "with APP_LOG_TO_FILE=false the interceptor does not patch console, but the stdio error " + + "guard must still be installed: structuredLogger writes to stderr directly in that " + + "configuration, so an async EPIPE would otherwise still become an uncaughtException" + ); +}); + +test("reset() removes the stream listeners and restores the original console methods", () => { + __consoleInterceptorInternals.reset(); + const baselineErrListeners = process.stderr.listenerCount("error"); + const pristineConsoleError = console.error; + + initConsoleInterceptor(); + assert.notEqual( + console.error, + pristineConsoleError, + "sanity: init must actually patch console.error" + ); + + __consoleInterceptorInternals.reset(); + + assert.equal( + process.stderr.listenerCount("error"), + baselineErrListeners, + "reset() must remove the listeners it added — otherwise repeated init across test files " + + "under --test-isolation=none accumulates listeners" + ); + assert.equal( + console.error, + pristineConsoleError, + "reset() must restore the original console.error — 136 test sites mock console, and a " + + "leaked patched method would be captured by their save/restore" + ); +}); + +test("re-init after reset() does not double-register stream listeners", () => { + __consoleInterceptorInternals.reset(); + const baseline = process.stderr.listenerCount("error"); + + initConsoleInterceptor(); + const afterFirst = process.stderr.listenerCount("error"); + __consoleInterceptorInternals.reset(); + initConsoleInterceptor(); + const afterSecond = process.stderr.listenerCount("error"); + + assert.equal(afterSecond, afterFirst, "listener count must not grow across reset/re-init cycles"); + assert.ok(afterFirst > baseline, "sanity: init must add a listener"); +}); + +test.after(() => { + __consoleInterceptorInternals.reset(); + + if (prevLogToFile === undefined) delete process.env.APP_LOG_TO_FILE; + else process.env.APP_LOG_TO_FILE = prevLogToFile; + + if (prevLogFilePath === undefined) delete process.env.APP_LOG_FILE_PATH; + else process.env.APP_LOG_FILE_PATH = prevLogFilePath; + + if (existsSync(dir)) rmSync(dir, { recursive: true, force: true }); +}); diff --git a/tests/unit/lib/consoleInterceptor-writes.test.ts b/tests/unit/lib/consoleInterceptor-writes.test.ts new file mode 100644 index 0000000000..8a16c244d7 --- /dev/null +++ b/tests/unit/lib/consoleInterceptor-writes.test.ts @@ -0,0 +1,172 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { mkdtempSync, rmSync, writeFileSync, readFileSync, existsSync } from "node:fs"; +import { spawnSync } from "node:child_process"; +import { fileURLToPath } from "node:url"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +// Issue #8181 companion coverage for the two write-path defects in consoleInterceptor: +// +// * writeEntry appends with no rate limit, so a flood writes unbounded lines to disk. The +// limiter added for this is scoped to `error` ONLY — structuredLogger's #1006 limiter is +// applied solely to error()/fatal(), while writeEntry serves all five console levels across +// ~800 non-error call sites. Capping those would silently drop routine logging. +// * ensureDir() runs once at init, so a directory removed at runtime makes every later append +// throw ENOENT into a bare catch, permanently and silently. +// +// These run in child processes for two reasons: the flood test would otherwise emit thousands +// of passthrough lines into the test runner's own output, and each child gets a private +// APP_LOG_FILE_PATH so line counts are attributable to the interceptor alone (structuredLogger +// and the pino transport also target the shared default log path). + +const interceptorPath = fileURLToPath( + new URL("../../../src/lib/consoleInterceptor.ts", import.meta.url) +); + +type ChildResult = { status: number | null; stderr: string; lines: Array> }; + +function runChild(body: string[]): ChildResult { + const dir = mkdtempSync(join(tmpdir(), "omniroute-writes-8181-")); + const logFile = join(dir, "logs", "application", "app.log"); + const childFile = join(dir, "probe.mts"); + + writeFileSync( + childFile, + [ + `process.env.APP_LOG_TO_FILE = "true";`, + `process.env.APP_LOG_FILE_PATH = ${JSON.stringify(logFile)};`, + `const M = await import(${JSON.stringify(interceptorPath)});`, + `const LOG_FILE = ${JSON.stringify(logFile)};`, + ...body, + ].join("\n") + ); + + const result = spawnSync(process.execPath, ["--import", "tsx/esm", childFile], { + encoding: "utf8", + timeout: 60_000, + env: { ...process.env, DISABLE_SQLITE_AUTO_BACKUP: "true" }, + }); + + const lines = existsSync(logFile) + ? readFileSync(logFile, "utf8") + .trim() + .split("\n") + .filter(Boolean) + .map((l) => JSON.parse(l) as Record) + : []; + + rmSync(dir, { recursive: true, force: true }); + return { status: result.status, stderr: String(result.stderr), lines }; +} + +test("a flood of identical console.error entries collapses to a single disk write (#8181)", () => { + const r = runChild([ + `M.initConsoleInterceptor();`, + `for (let i = 0; i < 10000; i++) console.error("identical flood line");`, + `setTimeout(() => process.exit(0), 150);`, + ]); + + assert.equal(r.status, 0, `child must exit cleanly: ${r.stderr.slice(0, 400)}`); + const flood = r.lines.filter((l) => l.message === "identical flood line"); + assert.equal( + flood.length, + 1, + `10,000 identical error entries inside the dedup window must yield exactly 1 disk line, got ${flood.length}` + ); +}); + +test("distinct error entries are capped per second, not unbounded (#8181)", () => { + const r = runChild([ + `M.initConsoleInterceptor();`, + `for (let i = 0; i < 500; i++) console.error("distinct error " + i);`, + `setTimeout(() => process.exit(0), 150);`, + ]); + + assert.equal(r.status, 0, `child must exit cleanly: ${r.stderr.slice(0, 400)}`); + const errs = r.lines.filter((l) => l.level === "error"); + assert.ok( + errs.length <= 51, + `500 distinct errors in one second must be capped near 50/sec, got ${errs.length}` + ); + assert.ok(errs.length > 0, "the cap must not suppress everything"); +}); + +// The R6 regression guard. If the limiter were applied to every level (the obvious way to write +// it), ordinary logging would be silently dropped and the Console Log Viewer would go sparse. +test("ordinary non-error logging is NOT rate limited (#8181)", () => { + const r = runChild([ + `M.initConsoleInterceptor();`, + `for (let i = 0; i < 300; i++) console.log("routine line " + i);`, + `for (let i = 0; i < 300; i++) console.warn("warn line " + i);`, + `setTimeout(() => process.exit(0), 200);`, + ]); + + assert.equal(r.status, 0, `child must exit cleanly: ${r.stderr.slice(0, 400)}`); + const routine = r.lines.filter((l) => l.message?.startsWith("routine line")); + const warns = r.lines.filter((l) => l.message?.startsWith("warn line")); + assert.equal( + routine.length, + 300, + `all 300 info entries must land — the limiter must be scoped to 'error' only, got ${routine.length}` + ); + assert.equal(warns.length, 300, `all 300 warn entries must land, got ${warns.length}`); +}); + +test("a single ordinary console.error still writes exactly one line", () => { + const r = runChild([ + `M.initConsoleInterceptor();`, + `console.error("just one");`, + `setTimeout(() => process.exit(0), 150);`, + ]); + + assert.equal(r.status, 0, `child must exit cleanly: ${r.stderr.slice(0, 400)}`); + assert.equal(r.lines.filter((l) => l.message === "just one").length, 1); +}); + +// This is the production incident, as a regression test: the log directory vanished across a +// restart and the interceptor stopped writing permanently, with nothing surfaced anywhere. +test("a log directory removed at runtime is recreated and logging recovers (#8181)", () => { + const r = runChild([ + `const { rmSync, existsSync } = await import("node:fs");`, + `const { dirname } = await import("node:path");`, + `M.initConsoleInterceptor();`, + `console.error("before removal");`, + `rmSync(dirname(LOG_FILE), { recursive: true, force: true });`, + `if (existsSync(LOG_FILE)) { process.exit(3); }`, + `console.error("after removal");`, + `setTimeout(() => process.exit(0), 200);`, + ]); + + assert.equal(r.status, 0, `child must exit cleanly: ${r.stderr.slice(0, 400)}`); + const messages = r.lines.map((l) => l.message); + assert.ok( + messages.includes("after removal"), + "an entry written after the log directory was deleted must still land — ensureDir() only " + + "runs at init, so without a retry the interceptor dies silently and permanently" + ); +}); + +test("the log-unavailable notice is emitted at most once, to the real stderr", () => { + const r = runChild([ + `const { rmSync, mkdirSync, chmodSync } = await import("node:fs");`, + `const { dirname } = await import("node:path");`, + `M.initConsoleInterceptor();`, + // Make the directory unrecreatable so the retry fails and the notice path is exercised. + `const parent = dirname(dirname(LOG_FILE));`, + `rmSync(dirname(LOG_FILE), { recursive: true, force: true });`, + `chmodSync(parent, 0o500);`, + `for (let i = 0; i < 5; i++) console.error("unwritable " + i);`, + `chmodSync(parent, 0o700);`, + `setTimeout(() => process.exit(0), 200);`, + ]); + + assert.equal(r.status, 0, `child must exit cleanly: ${r.stderr.slice(0, 400)}`); + const notices = r.stderr.split("\n").filter((l) => l.includes("[consoleInterceptor]")); + assert.equal( + notices.length, + 1, + `the notice must fire exactly once across repeated failures, got ${notices.length} — a ` + + "per-call notice would itself become a flood" + ); +}); diff --git a/tests/unit/shared/structuredLogger-raw-write-guard.test.ts b/tests/unit/shared/structuredLogger-raw-write-guard.test.ts new file mode 100644 index 0000000000..f0cf34997b --- /dev/null +++ b/tests/unit/shared/structuredLogger-raw-write-guard.test.ts @@ -0,0 +1,107 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { mkdtempSync, rmSync, writeFileSync, readFileSync, existsSync } from "node:fs"; +import { spawnSync } from "node:child_process"; +import { fileURLToPath } from "node:url"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +// Issue #8181: `error()` and `fatal()` write to stderr with a raw `process.stderr.write` +// wrapped in `try {} catch {}`. The comment on that line says the raw write exists to avoid +// Next.js console patching "that triggers EPIPE loops" — but on a broken pipe the write fails +// ASYNCHRONOUSLY, so the catch never sees it. The stream emits 'error', and with no listener +// attached Node re-throws it as an uncaughtException. That is the ignition point of the loop. +// +// consoleInterceptor now attaches the listener that breaks the cycle; this guard is defence in +// depth so a known-dead stream is not written to at all. +const { __structuredLoggerInternals } = + await import("../../../src/shared/utils/structuredLogger.ts"); + +test("isStreamWritable rejects a destroyed stream", () => { + assert.equal(__structuredLoggerInternals.isStreamWritable({ destroyed: true }), false); +}); + +test("isStreamWritable rejects an ended stream", () => { + assert.equal(__structuredLoggerInternals.isStreamWritable({ writableEnded: true }), false); +}); + +test("isStreamWritable accepts a healthy stream", () => { + assert.equal( + __structuredLoggerInternals.isStreamWritable({ destroyed: false, writableEnded: false }), + true + ); + // A stream object exposing neither flag (some fakes, and older stream shims) must not be + // treated as dead — the guard is only allowed to skip writes it is certain about. + assert.equal(__structuredLoggerInternals.isStreamWritable({}), true); +}); + +// The behavioural half. process.stderr cannot be destroyed in-process — the test runner writes +// its own diagnostics there — so this runs in a child, which also proves the property that +// actually matters: the process survives and file logging still happens. +test("error() with a destroyed stderr does not crash, and still writes to the log file (#8181)", () => { + const loggerPath = fileURLToPath( + new URL("../../../src/shared/utils/structuredLogger.ts", import.meta.url) + ); + const dir = mkdtempSync(join(tmpdir(), "omniroute-rawwrite-8181-")); + const logFile = join(dir, "logs", "application", "app.log"); + const childFile = join(dir, "probe.mts"); + + writeFileSync( + childFile, + [ + `process.env.APP_LOG_TO_FILE = "true";`, + `process.env.APP_LOG_FILE_PATH = ${JSON.stringify(logFile)};`, + `process.env.APP_LOG_LEVEL = "debug";`, + `const { createLogger } = await import(${JSON.stringify(loggerPath)});`, + `const log = createLogger("guard-probe");`, + `process.stderr.destroy();`, // the dead-stream condition + `log.error("entry after stderr destroyed");`, + `log.fatal("fatal after stderr destroyed");`, + `setTimeout(() => process.exit(0), 200);`, + ].join("\n") + ); + + const result = spawnSync(process.execPath, ["--import", "tsx/esm", childFile], { + encoding: "utf8", + timeout: 30_000, + env: { ...process.env, DISABLE_SQLITE_AUTO_BACKUP: "true" }, + }); + + assert.equal( + result.status, + 0, + `logging to a destroyed stderr must not crash the process; got exit ${result.status}` + ); + + assert.ok(existsSync(logFile), "the file sink must still receive entries when stderr is dead"); + const lines = readFileSync(logFile, "utf8") + .trim() + .split("\n") + .filter(Boolean) + .map((l) => JSON.parse(l)); + const messages = lines.map((l: { message?: string }) => l.message); + assert.ok( + messages.includes("entry after stderr destroyed"), + "error() must still reach writeToFile after the stderr write is skipped" + ); + assert.ok( + messages.includes("fatal after stderr destroyed"), + "fatal() must still reach writeToFile after the stderr write is skipped" + ); + + rmSync(dir, { recursive: true, force: true }); +}); + +// Guard against collateral damage: #1006's suppression policy must be untouched by this change. +test("the #1006 dedup/rate-limit policy is unchanged", () => { + assert.equal( + __structuredLoggerInternals.MAX_TRACKED_ERRORS, + 500, + "MAX_TRACKED_ERRORS is part of the accepted #1006 policy and must not drift" + ); + assert.equal( + typeof __structuredLoggerInternals.pruneRecentErrors, + "function", + "pruneRecentErrors must remain exported for the existing dedup-bound test" + ); +});