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" + ); +});