From cc5f596b5f83cdaf278021aee7ebfb608e17e63b Mon Sep 17 00:00:00 2001 From: Diego Rodrigues de Sa e Souza <8016841+diegosouzapw@users.noreply.github.com> Date: Tue, 7 Jul 2026 21:01:11 -0300 Subject: [PATCH] fix(logger): tolerate write to removed DATA_DIR so tests don't crash on teardown (#6360) (#6599) --- src/shared/utils/logger.ts | 109 +++++++++++------- ...r-write-after-datadir-removed-6360.test.ts | 109 ++++++++++++++++++ 2 files changed, 179 insertions(+), 39 deletions(-) create mode 100644 tests/unit/logger-write-after-datadir-removed-6360.test.ts diff --git a/src/shared/utils/logger.ts b/src/shared/utils/logger.ts index ff71dd6be5..83c79a9b39 100644 --- a/src/shared/utils/logger.ts +++ b/src/shared/utils/logger.ts @@ -47,6 +47,34 @@ function getTransportCompatibleConfig(): pino.LoggerOptions { return Object.keys(safeFormatters).length > 0 ? { ...rest, formatters: safeFormatters } : rest; } +/** + * Build a `pino.transport()` worker-thread stream and attach an `error` listener + * BEFORE handing it to `pino()`. + * + * `pino({ transport: {...} })` builds the same stream internally but never listens + * for its `error` event. A destination that stops existing mid-run (its directory is + * deleted — e.g. a test's tmp `DATA_DIR` removed in `after()`, or an operator wiping + * `logs/`) makes the worker's write fail with `ENOENT`; that surfaces as an unlistened + * `error` event on the main-thread stream, which Node re-throws as an uncaught + * exception (issue #6360 — "resource generated asynchronous activity after the test + * ended"). A logger must never crash its host process because its own log file + * vanished, so failed writes are dropped (best-effort stderr notice) instead of + * escalating. + */ +function buildFileTransportStream(targets: NonNullable) { + const stream = pino.transport({ targets }); + stream.on("error", (err: unknown) => { + try { + process.stderr.write( + `[logger] log transport write failed, dropping log line: ${(err as Error)?.message || err}\n` + ); + } catch { + // Nothing more we can do — never let a logging failure crash the process. + } + }); + return stream; +} + /** * Build the logger with optional file transport. * Uses pino transport targets for all destinations. @@ -67,49 +95,43 @@ function buildLogger(): pino.Logger { if (isDev) { // Dev: pino-pretty → stdout, JSON → file - return pino({ - ...transportConfig, - transport: { - targets: [ - { - target: "pino-pretty", - options: { - colorize: true, - translateTime: "HH:MM:ss.l", - ignore: "pid,hostname,service", - messageFormat: "[{module}] {msg}", - destination: 1, - }, - level: logLevel, - }, - { - target: "pino/file", - options: { destination: absLogPath, mkdir: true }, - level: logLevel, - }, - ], + const stream = buildFileTransportStream([ + { + target: "pino-pretty", + options: { + colorize: true, + translateTime: "HH:MM:ss.l", + ignore: "pid,hostname,service", + messageFormat: "[{module}] {msg}", + destination: 1, + }, + level: logLevel, }, - }); + { + target: "pino/file", + options: { destination: absLogPath, mkdir: true }, + level: logLevel, + }, + ]); + return pino(transportConfig, stream); } // Production: JSON → stdout + JSON → file - return pino({ - ...transportConfig, - transport: { - targets: [ - { - target: "pino/file", - options: { destination: 1 }, // stdout - level: logLevel, - }, - { - target: "pino/file", - options: { destination: absLogPath, mkdir: true }, - level: logLevel, - }, - ], - }, - }); + { + const stream = buildFileTransportStream([ + { + target: "pino/file", + options: { destination: 1 }, // stdout + level: logLevel, + }, + { + target: "pino/file", + options: { destination: absLogPath, mkdir: true }, + level: logLevel, + }, + ]); + return pino(transportConfig, stream); + } } catch (err) { // Log the actual error for diagnostics (issue #165) try { @@ -123,6 +145,15 @@ function buildLogger(): pino.Logger { try { const absLogPath = resolve(logConfig.logFilePath); const fileDestination = pino.destination({ dest: absLogPath, mkdir: true, sync: true }); + fileDestination.on("error", (err: unknown) => { + try { + process.stderr.write( + `[logger] sync log destination write failed, dropping log line: ${(err as Error)?.message || err}\n` + ); + } catch { + // Nothing more we can do — never let a logging failure crash the process. + } + }); // Production fallback: JSON to both stdout and file via multistream return pino( diff --git a/tests/unit/logger-write-after-datadir-removed-6360.test.ts b/tests/unit/logger-write-after-datadir-removed-6360.test.ts new file mode 100644 index 0000000000..26c6c2858c --- /dev/null +++ b/tests/unit/logger-write-after-datadir-removed-6360.test.ts @@ -0,0 +1,109 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { mkdtempSync, rmSync, existsSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import pino from "pino"; + +// Issue #6360: under CI load, unit-test FILES intermittently fail with +// "A resource generated asynchronous activity after the test ended ... +// ENOENT: no such file or directory, open '.../logs/application/app.log'" +// even though every subtest in the file passed. Root cause: the pino file +// transport is a worker-thread stream (`pino.transport()`, a `ThreadStream`) +// that opens/writes its destination asynchronously. `pino({ transport: {...} })` +// builds that stream internally but never attaches an `error` listener to it. +// When a test's `after()` hook removes the tmp DATA_DIR the log file lives +// under (as every test file's teardown already does) while the worker's +// open()/write() is still in flight, the worker reports the failure back as +// an `error` event on the main-thread stream — and since nothing is +// listening, Node's EventEmitter re-throws it as an uncaughtException. node:test +// then blames whichever file happens to be running when the async round-trip +// lands, which is why the failure moves between files on every rerun. +// +// We reproduce the exact mechanism deterministically (rather than racing real +// worker-thread timing, which is what makes the bug flaky in the first place): +// grab the real transport stream pino built via the public `pino.symbols.streamSym` +// handle and emit the same `error` event the worker would emit on a real ENOENT, +// after removing the tmp DATA_DIR exactly like a test teardown does. +// +// Configure file logging BEFORE importing the logger (buildLogger runs at import time). +const dir = mkdtempSync(join(tmpdir(), "omniroute-logger-6360-")); +const logFile = join(dir, "logs", "application", "app.log"); +process.env.NODE_ENV = "production"; // JSON to file, simplest single-target-per-destination path +process.env.APP_LOG_TO_FILE = "true"; +process.env.APP_LOG_FILE_PATH = logFile; +process.env.APP_LOG_LEVEL = "debug"; + +const { logger } = await import("../../src/shared/utils/logger.ts"); + +function flushLogger(): Promise { + return new Promise((resolveFlush) => { + try { + logger.flush(() => resolveFlush()); + } catch { + resolveFlush(); + } + }); +} + +test("logger's file transport stream carries an error listener (never an unhandled worker error)", () => { + const stream = (logger as unknown as Record)[pino.symbols.streamSym] as { + listenerCount(event: string): number; + }; + assert.ok(stream, "expected to retrieve the pino transport stream via pino.symbols.streamSym"); + assert.ok( + stream.listenerCount("error") > 0, + "the file-transport stream must have an 'error' listener attached — otherwise a worker " + + "write failure (e.g. ENOENT after DATA_DIR is removed) re-throws as an uncaughtException (#6360)" + ); +}); + +test("logger must not crash the process when its worker transport reports a write failure after DATA_DIR is removed (#6360)", async () => { + let uncaught: unknown = null; + const onUncaughtException = (err: unknown) => { + uncaught = err; + }; + process.on("uncaughtException", onUncaughtException); + + try { + logger.info({ phase: "before-removal" }, "line before DATA_DIR removal"); + + // Simulate the teardown every test file already does: rip out DATA_DIR + // while the logger's worker-thread transport is still alive. + rmSync(dir, { recursive: true, force: true }); + assert.equal(existsSync(dir), false, "sanity: DATA_DIR must actually be gone"); + + // Simulate the worker thread reporting the resulting write failure back to + // the main thread — exactly what sonic-boom/thread-stream does on a real + // ENOENT from a vanished destination directory. + const stream = (logger as unknown as Record)[pino.symbols.streamSym] as { + emit(event: string, ...args: unknown[]): boolean; + }; + stream.emit( + "error", + Object.assign(new Error(`ENOENT: no such file or directory, open '${logFile}'`), { + code: "ENOENT", + }) + ); + + // Give any (mis)handling a tick to surface as an uncaughtException before + // we assert — this is exactly the window in which #6360 fired "after the + // test ended". + await new Promise((r) => setTimeout(r, 50)); + + assert.equal( + uncaught, + null, + `logger transport write failure after DATA_DIR removal must not raise an uncaughtException: ${String(uncaught)}` + ); + } finally { + process.removeListener("uncaughtException", onUncaughtException); + } +}); + +test.after(async () => { + await flushLogger(); + if (existsSync(dir)) { + rmSync(dir, { recursive: true, force: true }); + } +});