mirror of
https://github.com/diegosouzapw/OmniRoute.git
synced 2026-08-17 04:32:31 +03:00
* 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
250 lines
8.1 KiB
TypeScript
250 lines
8.1 KiB
TypeScript
/**
|
|
* Structured Logger — FASE-05 Code Quality
|
|
*
|
|
* Lightweight structured logging wrapper with JSON output for production
|
|
* and human-readable output for development. Replaces scattered console.log
|
|
* calls with consistent, parseable log entries.
|
|
*
|
|
* When APP_LOG_TO_FILE is enabled, log entries are also appended as JSON lines
|
|
* to the application log file for the Console Log Viewer.
|
|
*
|
|
* @module shared/utils/structuredLogger
|
|
*/
|
|
|
|
import { getCorrelationId } from "../middleware/correlationId";
|
|
import { appendFileSync, existsSync, mkdirSync } from "fs";
|
|
import { dirname, resolve } from "path";
|
|
import { getAppLogFilePath, getAppLogLevel, getAppLogToFile } from "@/lib/logEnv";
|
|
|
|
const LOG_LEVELS: Record<string, number> = {
|
|
debug: 10,
|
|
info: 20,
|
|
warn: 30,
|
|
error: 40,
|
|
fatal: 50,
|
|
};
|
|
|
|
const currentLevel = LOG_LEVELS[getAppLogLevel("info").toLowerCase() || ""] || LOG_LEVELS.info;
|
|
const isProduction = process.env.NODE_ENV === "production";
|
|
|
|
// File logging configuration
|
|
const logToFile = getAppLogToFile();
|
|
const logFilePath = resolve(getAppLogFilePath());
|
|
|
|
// Ensure log directory exists once at module load
|
|
if (logToFile) {
|
|
try {
|
|
const dir = dirname(logFilePath);
|
|
if (!existsSync(dir)) {
|
|
mkdirSync(dir, { recursive: true });
|
|
}
|
|
} catch {
|
|
// silently ignore — will retry on each write
|
|
}
|
|
}
|
|
|
|
/**
|
|
* Append a JSON log line to the log file (non-blocking best-effort).
|
|
*/
|
|
function writeToFile(entry: Record<string, unknown>) {
|
|
if (!logToFile) return;
|
|
try {
|
|
appendFileSync(logFilePath, JSON.stringify(entry) + "\n");
|
|
} catch {
|
|
// Silently fail — file logging should never break the app
|
|
}
|
|
}
|
|
|
|
function formatEntry(
|
|
level: string,
|
|
component: string,
|
|
message: string,
|
|
meta?: Record<string, unknown>
|
|
) {
|
|
const entry: Record<string, unknown> = {
|
|
timestamp: new Date().toISOString(),
|
|
level,
|
|
component,
|
|
message,
|
|
...meta,
|
|
};
|
|
|
|
// Add correlation ID if available
|
|
const correlationId = getCorrelationId() as string | undefined;
|
|
if (correlationId) {
|
|
entry.correlationId = correlationId;
|
|
}
|
|
|
|
if (isProduction) {
|
|
return JSON.stringify(entry);
|
|
}
|
|
|
|
// Human-readable for development
|
|
const metaStr = meta && Object.keys(meta).length > 0 ? ` ${JSON.stringify(meta)}` : "";
|
|
const corrStr = correlationId ? ` [${correlationId.slice(0, 8)}]` : "";
|
|
return `[${entry.timestamp}] ${level.toUpperCase().padEnd(5)} [${component}]${corrStr} ${message}${metaStr}`;
|
|
}
|
|
|
|
function buildEntry(
|
|
level: string,
|
|
component: string,
|
|
message: string,
|
|
meta?: Record<string, unknown>
|
|
) {
|
|
const entry: Record<string, unknown> = {
|
|
timestamp: new Date().toISOString(),
|
|
level,
|
|
component,
|
|
message,
|
|
...meta,
|
|
};
|
|
const correlationId = getCorrelationId() as string | undefined;
|
|
if (correlationId) {
|
|
entry.correlationId = correlationId;
|
|
}
|
|
return entry;
|
|
}
|
|
|
|
// EPIPE-safe error deduplication + rate limiting (#1006)
|
|
const _recentErrors = new Map<string, { count: number; firstSeen: number }>();
|
|
const DEDUP_WINDOW_MS = 5_000;
|
|
const MAX_WRITES_PER_SECOND = 50;
|
|
// Hard cap on tracked distinct error messages. The age-based cleanup only removes entries
|
|
// older than DEDUP_WINDOW_MS, so a burst of >100 *unique* messages within a single 5s window
|
|
// (e.g. messages embedding request ids / urls / timestamps) could outpace it and grow the map.
|
|
// This bound evicts the oldest entries (Map preserves insertion order) as a backstop.
|
|
const MAX_TRACKED_ERRORS = 500;
|
|
let _writeCount = 0;
|
|
let _writeWindowStart = Date.now();
|
|
|
|
function pruneRecentErrors(now: number): void {
|
|
// Age-based cleanup of expired entries.
|
|
if (_recentErrors.size > 100) {
|
|
for (const [key, entry] of _recentErrors) {
|
|
if (now - entry.firstSeen > DEDUP_WINDOW_MS) _recentErrors.delete(key);
|
|
}
|
|
}
|
|
// Hard size cap: evict oldest (insertion-order) entries if a unique-message burst outpaced
|
|
// the age-based cleanup.
|
|
if (_recentErrors.size >= MAX_TRACKED_ERRORS) {
|
|
const overflow = _recentErrors.size - MAX_TRACKED_ERRORS + 1;
|
|
let removed = 0;
|
|
for (const key of _recentErrors.keys()) {
|
|
if (removed >= overflow) break;
|
|
_recentErrors.delete(key);
|
|
removed++;
|
|
}
|
|
}
|
|
}
|
|
|
|
function shouldSuppressError(message: string): boolean {
|
|
const now = Date.now();
|
|
|
|
// Rate limit: max writes per second
|
|
if (now - _writeWindowStart > 1000) {
|
|
_writeCount = 0;
|
|
_writeWindowStart = now;
|
|
}
|
|
if (_writeCount >= MAX_WRITES_PER_SECOND) return true;
|
|
|
|
// Dedup: suppress identical messages within window
|
|
const existing = _recentErrors.get(message);
|
|
if (existing && now - existing.firstSeen < DEDUP_WINDOW_MS) {
|
|
existing.count++;
|
|
return true;
|
|
}
|
|
|
|
pruneRecentErrors(now);
|
|
|
|
_recentErrors.set(message, { count: 1, firstSeen: now });
|
|
_writeCount++;
|
|
return false;
|
|
}
|
|
|
|
/** Test-only internals for verifying the dedup-map bound. */
|
|
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<string, unknown>) {
|
|
if (currentLevel <= LOG_LEVELS.debug) {
|
|
const entry = buildEntry("debug", component, message, meta);
|
|
console.debug(formatEntry("debug", component, message, meta));
|
|
writeToFile(entry);
|
|
}
|
|
},
|
|
info(message: string, meta?: Record<string, unknown>) {
|
|
if (currentLevel <= LOG_LEVELS.info) {
|
|
const entry = buildEntry("info", component, message, meta);
|
|
console.info(formatEntry("info", component, message, meta));
|
|
writeToFile(entry);
|
|
}
|
|
},
|
|
warn(message: string, meta?: Record<string, unknown>) {
|
|
if (currentLevel <= LOG_LEVELS.warn) {
|
|
const entry = buildEntry("warn", component, message, meta);
|
|
console.warn(formatEntry("warn", component, message, meta));
|
|
writeToFile(entry);
|
|
}
|
|
},
|
|
error(message: string, meta?: Record<string, unknown>) {
|
|
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.
|
|
// 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<string, unknown>) {
|
|
if (shouldSuppressError(message)) return;
|
|
const entry = buildEntry("fatal", component, message, meta);
|
|
safeStderrWrite(formatEntry("fatal", component, message, meta) + "\n");
|
|
writeToFile(entry);
|
|
},
|
|
child(defaultMeta: Record<string, unknown>) {
|
|
return createLogger(component);
|
|
},
|
|
};
|
|
}
|
|
|
|
export { LOG_LEVELS };
|