From 08b280d5505bda9c1636963ee9650e19c33d7965 Mon Sep 17 00:00:00 2001 From: usr-bin-roygbiv Date: Tue, 28 Jul 2026 14:06:55 +0000 Subject: [PATCH] perf(utils): avoid Winston runtime dispatch (cherry picked from commit e5aeff8153551c8c4a5cb6a47c7ed00cba32000f) --- packages/utils/CHANGELOG.md | 4 + packages/utils/src/logger.ts | 171 +++++++++++------- .../utils/src/winston-daily-rotate-file.d.ts | 6 + packages/utils/test/logger-contract.test.ts | 19 +- 4 files changed, 130 insertions(+), 70 deletions(-) create mode 100644 packages/utils/src/winston-daily-rotate-file.d.ts diff --git a/packages/utils/CHANGELOG.md b/packages/utils/CHANGELOG.md index f70371acf..8c1d5608c 100644 --- a/packages/utils/CHANGELOG.md +++ b/packages/utils/CHANGELOG.md @@ -2,6 +2,10 @@ ## [Unreleased] +### Changed + +- Replaced the central logger's Winston dispatch with a byte-compatible local dispatcher while retaining the existing `winston-daily-rotate-file` rotation and retention behavior. + ## [17.1.8] - 2026-07-28 ### Added diff --git a/packages/utils/src/logger.ts b/packages/utils/src/logger.ts index 853505d5b..0e058c138 100644 --- a/packages/utils/src/logger.ts +++ b/packages/utils/src/logger.ts @@ -1,3 +1,5 @@ +/// + /** * Centralized logger for omp. * @@ -11,10 +13,11 @@ */ import { AsyncLocalStorage } from "node:async_hooks"; import * as fs from "node:fs"; +import * as os from "node:os"; import * as path from "node:path"; import { isPromise } from "node:util/types"; -import winston from "winston"; -import DailyRotateFile from "winston-daily-rotate-file"; +import type DailyRotateFile from "winston-daily-rotate-file"; +import DailyRotateFileImplementation from "winston-daily-rotate-file/daily-rotate-file.js"; import { getLogsDir } from "./dirs"; import { drainModuleLoadEvents } from "./timing-buffer"; /** Severity names accepted by the centralized logger. */ @@ -143,36 +146,68 @@ function jsonReplacer(_key: string, value: unknown): unknown { return value; } -/** Custom format that includes pid and flattens metadata; built on first use. */ -let logFormat: winston.Logform.Format | undefined; - -function getLogFormat(): winston.Logform.Format { - logFormat ??= winston.format.combine( - winston.format.timestamp({ format: "YYYY-MM-DDTHH:mm:ss.SSSZ" }), - winston.format.printf(({ timestamp, level, message, ...meta }) => { - const entry: Record = { - timestamp, - level, - pid: process.pid, - message, - }; - // Flatten metadata into entry - for (const [key, value] of Object.entries(meta)) { - if (key !== "level" && key !== "timestamp" && key !== "message") { - entry[key] = value; - } - } - return JSON.stringify(entry, jsonReplacer); - }), - ); - return logFormat; +interface NormalizedLogInfo extends Record { + level: LogLevel; + message: unknown; } +function padTimestampPart(value: number, width = 2): string { + return String(value).padStart(width, "0"); +} + +function formatLocalTimestamp(date: Date): string { + const offsetMinutes = -date.getTimezoneOffset(); + const absoluteOffset = Math.abs(offsetMinutes); + const offsetSign = offsetMinutes >= 0 ? "+" : "-"; + return ( + `${padTimestampPart(date.getFullYear(), 4)}-${padTimestampPart(date.getMonth() + 1)}-${padTimestampPart(date.getDate())}` + + `T${padTimestampPart(date.getHours())}:${padTimestampPart(date.getMinutes())}:${padTimestampPart(date.getSeconds())}` + + `.${padTimestampPart(date.getMilliseconds(), 3)}${offsetSign}${padTimestampPart(Math.floor(absoluteOffset / 60))}` + + `:${padTimestampPart(absoluteOffset % 60)}` + ); +} + +const FORMAT_TOKEN_PATTERN = /%[scdjifoO%]/; + +function normalizeLogInfo( + level: LogLevel, + message: string, + context: Record | undefined, +): NormalizedLogInfo { + const metadata = + !FORMAT_TOKEN_PATTERN.test(message) && context !== null && typeof context === "object" ? context : undefined; + const info = Object.assign({}, metadata, { level, message }) as NormalizedLogInfo; + if (metadata?.message) info.message = `${message} ${metadata.message}`; + if (metadata?.stack) info.stack = metadata.stack; + if (metadata?.cause) info.cause = metadata.cause; + return info; +} + +function formatLogInfo(info: NormalizedLogInfo): string { + const timestamp = formatLocalTimestamp(new Date()); + info.timestamp = timestamp; + const entry: Record = { + timestamp, + level: info.level, + pid: process.pid, + message: info.message, + }; + for (const [key, value] of Object.entries(info)) { + if (key !== "level" && key !== "timestamp" && key !== "message") entry[key] = value; + } + return JSON.stringify(entry, jsonReplacer) as string; +} + +type FileTransport = DailyRotateFile & { + log(info: Record, callback: () => void): void; + close(): void; +}; + /** Build a rotating file transport with process-local rotation and shared retention. */ -function makeFileTransport(dir?: string): winston.transport { +function makeFileTransport(dir?: string): FileTransport { const logsDir = ensureDir(dir ?? getLogsDir()); pruneStaleProcessLogs(logsDir); - return new DailyRotateFile({ + return new DailyRotateFileImplementation({ dirname: logsDir, filename: `omp.%DATE%.${process.pid}.log`, datePattern: "YYYY-MM-DD", @@ -180,45 +215,48 @@ function makeFileTransport(dir?: string): winston.transport { maxFiles: 5, zippedArchive: false, auditFile: path.join(logsDir, `.omp.${process.pid}-audit.json`), - }); -} - -function makeConsoleTransport(): winston.transport { - return new winston.transports.Console({ format: getLogFormat() }); + }) as FileTransport; } /** - * Desired transport configuration, applied when the winston logger is built. + * Desired transport configuration, applied when local logging is initialized. * Default: file ON (TUI-safe), console OFF. */ let transportOpts: { console?: boolean; file?: boolean | string } = { file: true }; -/** The winston logger instance, created lazily on first log emission. */ -let winstonLogger: winston.Logger | undefined; - -function buildTransports(opts: { console?: boolean; file?: boolean | string }): winston.transport[] { - const transports: winston.transport[] = []; - if (opts.file) transports.push(makeFileTransport(typeof opts.file === "string" ? opts.file : undefined)); - if (opts.console) transports.push(makeConsoleTransport()); - return transports; +interface LocalTransports { + readonly file: FileTransport | undefined; + readonly console: boolean; } -function getWinstonLogger(): winston.Logger { - if (!winstonLogger) { - const transports = buildTransports(transportOpts); - winstonLogger = winston.createLogger({ - level: "debug", - format: getLogFormat(), - transports, - // A transport-less winston logger console.warns "Attempt to write logs - // with no transports" on every emit; mark it silent instead so disabling - // all transports is a clean no-op. - silent: transports.length === 0, - // Don't exit on error - logging failures shouldn't crash the app - exitOnError: false, - }); - } - return winstonLogger; +/** Local transports, constructed lazily on first log emission. */ +let activeTransports: LocalTransports | undefined; + +const TRANSPORT_MESSAGE = Symbol.for("message"); +const onTransportLogged = (): void => {}; + +function buildTransports(opts: { console?: boolean; file?: boolean | string }): LocalTransports { + return { + file: opts.file ? makeFileTransport(typeof opts.file === "string" ? opts.file : undefined) : undefined, + console: opts.console === true, + }; +} + +function getLocalTransports(): LocalTransports { + activeTransports ??= buildTransports(transportOpts); + return activeTransports; +} + +function emitLocally(level: LogLevel, message: string, context: Record | undefined): void { + const transports = getLocalTransports(); + const info = normalizeLogInfo(level, message, context); + if (!transports.file && !transports.console) return; + + // Winston applied the shared format before dispatch, then the same format a + // second time inside Console. Keep those evaluation and timestamp semantics. + const line = formatLogInfo(info); + if (transports.file) transports.file.log({ [TRANSPORT_MESSAGE]: line }, onTransportLogged); + if (transports.console) process.stdout.write(`${formatLogInfo(info)}${os.EOL}`); } /** @@ -228,12 +266,11 @@ function getWinstonLogger(): winston.Logger { */ export function setTransports(opts: { console?: boolean; file?: boolean | string }): void { transportOpts = opts; - if (!winstonLogger) return; // applied lazily when the logger is first built - winstonLogger.clear(); - const transports = buildTransports(opts); - for (const transport of transports) winstonLogger.add(transport); - // Keep the logger silent when nothing is attached so winston doesn't warn on emit. - winstonLogger.silent = transports.length === 0; + if (!activeTransports) return; // applied lazily when local logging is first initialized + const previousTransports = activeTransports; + activeTransports = { file: undefined, console: false }; + previousTransports.file?.close(); + activeTransports = buildTransports(opts); } /** @@ -243,7 +280,7 @@ export function setTransports(opts: { console?: boolean; file?: boolean | string */ export function error(message: string, context?: Record): void { try { - getWinstonLogger().error(message, context); + emitLocally("error", message, context); } catch { // Silently ignore logging failures } @@ -257,7 +294,7 @@ export function error(message: string, context?: Record): void */ export function warn(message: string, context?: Record): void { try { - getWinstonLogger().warn(message, context); + emitLocally("warn", message, context); } catch { // Silently ignore logging failures } @@ -271,7 +308,7 @@ export function warn(message: string, context?: Record): void { */ export function info(message: string, context?: Record): void { try { - getWinstonLogger().info(message, context); + emitLocally("info", message, context); } catch { // Silently ignore logging failures } @@ -285,7 +322,7 @@ export function info(message: string, context?: Record): void { */ export function debug(message: string, context?: Record): void { try { - getWinstonLogger().debug(message, context); + emitLocally("debug", message, context); } catch { // Silently ignore logging failures } diff --git a/packages/utils/src/winston-daily-rotate-file.d.ts b/packages/utils/src/winston-daily-rotate-file.d.ts new file mode 100644 index 000000000..d55e02f58 --- /dev/null +++ b/packages/utils/src/winston-daily-rotate-file.d.ts @@ -0,0 +1,6 @@ +declare module "winston-daily-rotate-file/daily-rotate-file.js" { + import type DailyRotateFile from "winston-daily-rotate-file"; + + const DailyRotateFileImplementation: typeof DailyRotateFile; + export default DailyRotateFileImplementation; +} diff --git a/packages/utils/test/logger-contract.test.ts b/packages/utils/test/logger-contract.test.ts index 4bc25512b..58881d43e 100644 --- a/packages/utils/test/logger-contract.test.ts +++ b/packages/utils/test/logger-contract.test.ts @@ -70,7 +70,9 @@ async function runScenario(scenario: string): Promise { } async function logFileNames(directory: string): Promise { - return (await fs.readdir(directory)).filter(name => /^omp\.\d{4}-\d{2}-\d{2}\.\d+\.log(?:\.\d+)?$/.test(name)).sort(); + return (await fs.readdir(directory)) + .filter(name => /^omp\.\d{4}-\d{2}-\d{2}\.\d+\.log(?:\.\d+)?$/.test(name)) + .sort(); } async function readSingleLog(directory: string): Promise<{ name: string; text: string }> { @@ -134,7 +136,17 @@ describe("central logger byte contract", () => { const result = await runScenario("format-tokens"); expect(result.stdout).toBe(""); expect(result.stderr).toBe(""); - const tokenMessages = ["token-%s", "token-%c", "token-%d", "token-%j", "token-%i", "token-%f", "token-%o", "token-%O", "token-%%"]; + const tokenMessages = [ + "token-%s", + "token-%c", + "token-%d", + "token-%j", + "token-%i", + "token-%f", + "token-%o", + "token-%O", + "token-%%", + ]; const expected = [ ...tokenMessages.map(message => expectedLine(result.pid, "info", message)), expectedLine(result.pid, "info", "non-token-%q", { value: 7 }), @@ -297,7 +309,8 @@ describe("DailyRotateFile option and retention contract", () => { const basePath = path.join(result.primaryDir, baseName); const baseStat = await fs.stat(basePath); const recordSize = (message: string, payloadSize: number): number => - `{"timestamp":"${fixedTimestamp}","level":"info","pid":${result.pid},"message":"${message}","payload":"`.length + + `{"timestamp":"${fixedTimestamp}","level":"info","pid":${result.pid},"message":"${message}","payload":"` + .length + payloadSize + `"}${os.EOL}`.length; const expectedBytes =