perf(utils): avoid Winston runtime dispatch
(cherry picked from commit e5aeff8153551c8c4a5cb6a47c7ed00cba32000f)
This commit is contained in:
@@ -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
|
||||
|
||||
+104
-67
@@ -1,3 +1,5 @@
|
||||
/// <reference path="./winston-daily-rotate-file.d.ts" />
|
||||
|
||||
/**
|
||||
* 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<string, unknown> = {
|
||||
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<string, unknown> {
|
||||
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<string, unknown> | 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<string, unknown> = {
|
||||
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<symbol, string>, 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<string, unknown> | 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<string, unknown>): 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<string, unknown>): void
|
||||
*/
|
||||
export function warn(message: string, context?: Record<string, unknown>): 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<string, unknown>): void {
|
||||
*/
|
||||
export function info(message: string, context?: Record<string, unknown>): 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<string, unknown>): void {
|
||||
*/
|
||||
export function debug(message: string, context?: Record<string, unknown>): void {
|
||||
try {
|
||||
getWinstonLogger().debug(message, context);
|
||||
emitLocally("debug", message, context);
|
||||
} catch {
|
||||
// Silently ignore logging failures
|
||||
}
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
@@ -70,7 +70,9 @@ async function runScenario(scenario: string): Promise<ScenarioResult> {
|
||||
}
|
||||
|
||||
async function logFileNames(directory: string): Promise<string[]> {
|
||||
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 =
|
||||
|
||||
Reference in New Issue
Block a user