fix(dev): make logging resources HMR-singleton (#12079)

Co-authored-by: backryun <backryun@daonlab.local>
This commit is contained in:
backryun
2026-09-01 02:13:53 +09:00
committed by GitHub
parent e12fb110f9
commit f8b01c966e
8 changed files with 439 additions and 54 deletions

View File

@@ -137,6 +137,11 @@ function createNextApp() {
});
}
// The custom HTTP server owns process exit. Application instrumentation still
// registers its cleanup function, but must not install a competing signal
// listener that can race this runner's async server/Next teardown.
globalThis.__omnirouteCustomServerOwnsShutdown = true;
let nextApp = createNextApp();
// Best-effort self-heal for a corrupted Turbopack persistent dev cache (#6289):
@@ -231,6 +236,7 @@ async function start() {
systemdNotifier.stopping();
try {
await new Promise((resolve) => server.close(resolve));
await globalThis.__omnirouteRequestShutdown?.(signal);
await nextApp.close();
} catch (error) {
console.error("[SHUTDOWN] Failed during signal:", signal, error);

View File

@@ -19,7 +19,15 @@ const SHUTDOWN_TIMEOUT_MS = parseInt(process.env.SHUTDOWN_TIMEOUT_MS || "30000",
declare global {
var __omnirouteShutdown:
{ init: boolean; shuttingDown: boolean; activeRequests: number } | undefined;
| {
init: boolean;
shuttingDown: boolean;
activeRequests: number;
shutdownPromise?: Promise<void>;
}
| undefined;
var __omnirouteRequestShutdown: ((signal: string) => Promise<void>) | undefined;
var __omnirouteCustomServerOwnsShutdown: boolean | undefined;
}
function getShutdownState() {
@@ -102,12 +110,14 @@ async function cleanup(): Promise<void> {
{ closeDbInstance },
{ flushSpendBatchWriter },
{ closeLogRotation },
{ closeSharedLoggerResource },
{ closeCallLogSaves },
] = await Promise.all([
import("@omniroute/open-sse/mcp-server/audit.ts"),
import("@/lib/db/core"),
import("@/lib/spend/batchWriter"),
import("@/lib/logRotation"),
import("@/shared/utils/loggerResource"),
import("@/lib/usage/callLogs"),
]);
const flushResult = await flushSpendBatchWriter();
@@ -123,9 +133,6 @@ async function cleanup(): Promise<void> {
if (closeDbInstance()) {
console.log("[Shutdown] SQLite database checkpointed and closed.");
}
closeLogRotation();
console.log("[Shutdown] Log rotation timer stopped.");
// Tear down any persistent VNC login browser containers so they don't leak
// past the server process. Best-effort; no-op if the feature was never used
// or the docker CLI is unavailable.
@@ -147,41 +154,62 @@ async function cleanup(): Promise<void> {
} catch {
/* feature unused */
}
await closeSharedLoggerResource();
closeLogRotation();
console.log("[Shutdown] Logger transport and log rotation stopped.");
} catch (err) {
console.error("[Shutdown] Error during cleanup:", (err as Error).message);
}
}
/**
* Start the process-wide shutdown sequence, or join the sequence already in progress.
*/
export function requestGracefulShutdown(signal: string): Promise<void> {
const state = getShutdownState();
if (state.shutdownPromise) return state.shutdownPromise;
state.shuttingDown = true;
markServerStopping();
state.shutdownPromise = (async () => {
console.log(`\n[Shutdown] Received ${signal}. Draining ${state.activeRequests} request(s)...`);
await waitForDrain();
await cleanup();
console.log("[Shutdown] Bye.");
})();
return state.shutdownPromise;
}
/**
* Initialize graceful shutdown handlers.
* Should be called once during server startup.
*/
export function initGracefulShutdown(): void {
const state = getShutdownState();
globalThis.__omnirouteRequestShutdown ??= requestGracefulShutdown;
if (state.init) return;
state.init = true;
const shutdown = async (signal: string) => {
if (state.shuttingDown) return;
state.shuttingDown = true;
markServerStopping();
if (globalThis.__omnirouteCustomServerOwnsShutdown) {
console.log("[Shutdown] Cleanup registered with the custom server shutdown owner.");
return;
}
console.log(`\n[Shutdown] Received ${signal}. Draining ${state.activeRequests} request(s)...`);
await waitForDrain();
await cleanup();
console.log("[Shutdown] Bye.");
process.exit(0);
const shutdown = (signal: string) => {
void globalThis.__omnirouteRequestShutdown?.(signal).then(() => process.exit(0));
};
process.on("SIGTERM", () => shutdown("SIGTERM"));
process.on("SIGINT", () => shutdown("SIGINT"));
process.on("SIGTERM", () => void shutdown("SIGTERM"));
process.on("SIGINT", () => void shutdown("SIGINT"));
// #8045: on Windows, closing the console window delivers CTRL_CLOSE_EVENT, which
// Node/libuv maps to a JS-visible "SIGHUP" event — without this listener, closing
// the window never runs cleanup() (WAL checkpoint + closeDbInstance()), leaving
// storage.sqlite's WAL un-checkpointed for the next launch.
process.on("SIGHUP", () => shutdown("SIGHUP"));
process.on("SIGHUP", () => void shutdown("SIGHUP"));
console.log("[Shutdown] Graceful shutdown handlers registered.");
}

View File

@@ -42,8 +42,18 @@ export function getAppLogRotationCheckInterval(): number {
);
}
/** Module-level timer handle — cleared by closeLogRotation(). */
let rotationTimer: ReturnType<typeof setInterval> | null = null;
interface LogRotationState {
timer: ReturnType<typeof setInterval> | null;
}
declare global {
var __omnirouteLogRotationState: LogRotationState | undefined;
}
/** Process-wide state survives Next.js development HMR and split server chunks. */
function getLogRotationState(): LogRotationState {
return (globalThis.__omnirouteLogRotationState ??= { timer: null });
}
export function getLogConfig() {
const logToFile = getAppLogToFile();
@@ -172,6 +182,9 @@ export function cleanupOverflowLogs(logFilePath: string, maxFiles: number): void
* Call closeLogRotation() during application shutdown to clear the timer.
*/
export function initLogRotation(): void {
const state = getLogRotationState();
if (state.timer !== null) return;
const config = getLogConfig();
if (!config.logToFile) return;
@@ -181,7 +194,7 @@ export function initLogRotation(): void {
cleanupOverflowLogs(config.logFilePath, config.maxFiles);
const intervalMs = getAppLogRotationCheckInterval();
rotationTimer = setInterval(
state.timer = setInterval(
(filePath: string, maxSize: number, maxFiles: number) => {
rotateIfNeeded(filePath, maxSize);
cleanupOverflowLogs(filePath, maxFiles);
@@ -191,7 +204,7 @@ export function initLogRotation(): void {
config.maxFileSize,
config.maxFiles
);
rotationTimer.unref?.();
state.timer.unref?.();
}
/**
@@ -199,8 +212,9 @@ export function initLogRotation(): void {
* Idempotent — safe to call multiple times.
*/
export function closeLogRotation(): void {
if (rotationTimer !== null) {
clearInterval(rotationTimer);
rotationTimer = null;
const state = getLogRotationState();
if (state.timer !== null) {
clearInterval(state.timer);
state.timer = null;
}
}

View File

@@ -18,6 +18,10 @@ import { resolve } from "path";
import { getLogConfig, initLogRotation } from "@/lib/logRotation";
import { getAppLogLevel } from "@/lib/logEnv";
import { redactLogArgs } from "@/shared/utils/logRedaction";
import {
getOrCreateSharedLoggerResource,
type SharedLoggerResource,
} from "@/shared/utils/loggerResource";
const isDev = process.env.NODE_ENV !== "production";
@@ -61,7 +65,7 @@ function getTransportCompatibleConfig(): pino.LoggerOptions {
* vanished, so failed writes are dropped (best-effort stderr notice) instead of
* escalating.
*/
function buildFileTransportStream(targets: NonNullable<pino.TransportMultiOptions["targets"]>) {
function buildTransportStream(targets: NonNullable<pino.TransportMultiOptions["targets"]>) {
const stream = pino.transport({ targets });
stream.on("error", (err: unknown) => {
try {
@@ -75,11 +79,65 @@ function buildFileTransportStream(targets: NonNullable<pino.TransportMultiOption
return stream;
}
interface OwnedLogStream {
flushSync?: () => void;
end?: () => void;
once?: (event: string, listener: () => void) => unknown;
}
async function closeOwnedStream(stream: OwnedLogStream | null): Promise<void> {
if (!stream) return;
try {
stream.flushSync?.();
} catch {
// Best-effort shutdown: a missing log destination must not block process exit.
}
if (!stream.end) return;
await new Promise<void>((resolveClose) => {
let resolved = false;
const finish = () => {
if (resolved) return;
resolved = true;
resolveClose();
};
const fallback = setTimeout(finish, 1_000);
stream.once?.("close", () => {
clearTimeout(fallback);
finish();
});
try {
stream.end?.();
if (!stream.once) {
clearTimeout(fallback);
finish();
}
} catch {
clearTimeout(fallback);
finish();
}
});
}
function createLoggerResource(
logger: pino.Logger,
stream: OwnedLogStream | null
): SharedLoggerResource {
return {
logger,
close: () => closeOwnedStream(stream),
};
}
/**
* Build the logger with optional file transport.
* Uses pino transport targets for all destinations.
*/
function buildLogger(): pino.Logger {
function buildLoggerResource(): SharedLoggerResource {
const logConfig = getLogConfig();
const logLevel = (baseConfig.level as string) || "info";
const transportConfig = getTransportCompatibleConfig();
@@ -95,7 +153,7 @@ function buildLogger(): pino.Logger {
if (isDev) {
// Dev: pino-pretty → stdout, JSON → file
const stream = buildFileTransportStream([
const stream = buildTransportStream([
{
target: "pino-pretty",
options: {
@@ -113,12 +171,12 @@ function buildLogger(): pino.Logger {
level: logLevel,
},
]);
return pino(transportConfig, stream);
return createLoggerResource(pino(transportConfig, stream), stream);
}
// Production: JSON → stdout + JSON → file
{
const stream = buildFileTransportStream([
const stream = buildTransportStream([
{
target: "pino/file",
options: { destination: 1 }, // stdout
@@ -130,7 +188,7 @@ function buildLogger(): pino.Logger {
level: logLevel,
},
]);
return pino(transportConfig, stream);
return createLoggerResource(pino(transportConfig, stream), stream);
}
} catch (err) {
// Log the actual error for diagnostics (issue #165)
@@ -156,12 +214,15 @@ function buildLogger(): pino.Logger {
});
// Production fallback: JSON to both stdout and file via multistream
return pino(
baseConfig,
pino.multistream([
{ stream: process.stdout, level: logLevel as pino.Level },
{ stream: fileDestination, level: logLevel as pino.Level },
])
return createLoggerResource(
pino(
baseConfig,
pino.multistream([
{ stream: process.stdout, level: logLevel as pino.Level },
{ stream: fileDestination, level: logLevel as pino.Level },
])
),
fileDestination
);
} catch (fallbackErr) {
try {
@@ -175,9 +236,8 @@ function buildLogger(): pino.Logger {
// Console-only (no file logging)
if (isDev) {
return pino({
...baseConfig,
transport: {
const stream = buildTransportStream([
{
target: "pino-pretty",
options: {
colorize: true,
@@ -185,14 +245,18 @@ function buildLogger(): pino.Logger {
ignore: "pid,hostname,service",
messageFormat: "[{module}] {msg}",
},
level: logLevel,
},
});
]);
return createLoggerResource(pino(transportConfig, stream), stream);
}
return pino(baseConfig);
return createLoggerResource(pino(baseConfig), null);
}
export const logger = buildLogger();
const sharedLoggerResource = getOrCreateSharedLoggerResource(buildLoggerResource);
export const logger = sharedLoggerResource.logger;
/**
* Create a child logger with a module tag.

View File

@@ -0,0 +1,32 @@
import type { Logger } from "pino";
export interface SharedLoggerResource {
logger: Logger;
close: () => Promise<void>;
}
declare global {
var __omnirouteLoggerResource: SharedLoggerResource | undefined;
}
/**
* Return the process-wide logger resource, creating it only once.
*
* Next.js development HMR can evaluate logger.ts in more than one server chunk.
* Keeping the resource on globalThis prevents each evaluation from spawning a
* new pino worker transport.
*/
export function getOrCreateSharedLoggerResource(
create: () => SharedLoggerResource
): SharedLoggerResource {
return (globalThis.__omnirouteLoggerResource ??= create());
}
/** Close and forget the shared transport. Idempotent across HMR module copies. */
export async function closeSharedLoggerResource(): Promise<void> {
const resource = globalThis.__omnirouteLoggerResource;
if (!resource) return;
delete globalThis.__omnirouteLoggerResource;
await resource.close();
}

View File

@@ -1,5 +1,12 @@
import { test } from "node:test";
import assert from "node:assert/strict";
import { join } from "node:path";
import { pathToFileURL } from "node:url";
type GracefulShutdownModule = typeof import("../../src/lib/gracefulShutdown.ts");
const gracefulShutdownUrl = pathToFileURL(join(process.cwd(), "src/lib/gracefulShutdown.ts")).href;
const shutdownSignals = ["SIGTERM", "SIGINT", "SIGHUP"] as const;
// #8045: on Windows, closing the console window delivers CTRL_CLOSE_EVENT, which
// Node/libuv maps to a JS-visible "SIGHUP" event (confirmed: nodejs/node#10165,
@@ -7,17 +14,90 @@ import assert from "node:assert/strict";
// closed"). Before this fix, initGracefulShutdown() only registered SIGTERM/SIGINT,
// so the "close the window" path never ran cleanup() (WAL checkpoint(TRUNCATE) +
// closeDbInstance()), leaving storage.sqlite's WAL un-checkpointed for the next launch.
test("initGracefulShutdown registers a SIGHUP handler (Windows console-close path)", async () => {
const before = process.listenerCount("SIGHUP");
const { initGracefulShutdown } = await import("../../src/lib/gracefulShutdown.ts");
initGracefulShutdown();
const after = process.listenerCount("SIGHUP");
assert.ok(
after > before,
`Expected initGracefulShutdown() to add a SIGHUP listener (before=${before}, after=${after}).`
test("graceful shutdown listeners remain process-singletons across HMR module instances", async () => {
const previousState = globalThis.__omnirouteShutdown;
const previousRequestShutdown = globalThis.__omnirouteRequestShutdown;
const previousCustomServerOwner = globalThis.__omnirouteCustomServerOwnsShutdown;
const listenersBefore = new Map(
shutdownSignals.map((signal) => [signal, process.listeners(signal)] as const)
);
delete globalThis.__omnirouteShutdown;
delete globalThis.__omnirouteRequestShutdown;
delete globalThis.__omnirouteCustomServerOwnsShutdown;
try {
const first = (await import(
`${gracefulShutdownUrl}?phase4=shutdown-a`
)) as GracefulShutdownModule;
const second = (await import(
`${gracefulShutdownUrl}?phase4=shutdown-b`
)) as GracefulShutdownModule;
first.initGracefulShutdown();
assert.equal(globalThis.__omnirouteRequestShutdown, first.requestGracefulShutdown);
for (const signal of shutdownSignals) {
assert.equal(process.listenerCount(signal), listenersBefore.get(signal)!.length + 1);
}
second.initGracefulShutdown();
for (const signal of shutdownSignals) {
assert.equal(
process.listenerCount(signal),
listenersBefore.get(signal)!.length + 1,
`${signal} listener must not be duplicated by HMR re-initialization`
);
}
} finally {
for (const signal of shutdownSignals) {
const previousListeners = listenersBefore.get(signal)!;
for (const listener of process.listeners(signal)) {
if (!previousListeners.includes(listener)) process.removeListener(signal, listener);
}
}
if (previousState === undefined) delete globalThis.__omnirouteShutdown;
else globalThis.__omnirouteShutdown = previousState;
if (previousRequestShutdown === undefined) delete globalThis.__omnirouteRequestShutdown;
else globalThis.__omnirouteRequestShutdown = previousRequestShutdown;
if (previousCustomServerOwner === undefined) {
delete globalThis.__omnirouteCustomServerOwnsShutdown;
} else {
globalThis.__omnirouteCustomServerOwnsShutdown = previousCustomServerOwner;
}
}
});
test("a custom server owner receives cleanup without duplicate process signal listeners", async () => {
const previousState = globalThis.__omnirouteShutdown;
const previousRequestShutdown = globalThis.__omnirouteRequestShutdown;
const previousCustomServerOwner = globalThis.__omnirouteCustomServerOwnsShutdown;
const listenerCounts = new Map(
shutdownSignals.map((signal) => [signal, process.listenerCount(signal)] as const)
);
// Clean up: remove all SIGHUP listeners added by this test so it doesn't leak
// into other test files sharing the same process.
process.removeAllListeners("SIGHUP");
delete globalThis.__omnirouteShutdown;
delete globalThis.__omnirouteRequestShutdown;
globalThis.__omnirouteCustomServerOwnsShutdown = true;
try {
const shutdownModule = (await import(
`${gracefulShutdownUrl}?phase4=custom-owner`
)) as GracefulShutdownModule;
shutdownModule.initGracefulShutdown();
assert.equal(globalThis.__omnirouteRequestShutdown, shutdownModule.requestGracefulShutdown);
for (const signal of shutdownSignals) {
assert.equal(process.listenerCount(signal), listenerCounts.get(signal));
}
} finally {
if (previousState === undefined) delete globalThis.__omnirouteShutdown;
else globalThis.__omnirouteShutdown = previousState;
if (previousRequestShutdown === undefined) delete globalThis.__omnirouteRequestShutdown;
else globalThis.__omnirouteRequestShutdown = previousRequestShutdown;
if (previousCustomServerOwner === undefined) {
delete globalThis.__omnirouteCustomServerOwnsShutdown;
} else {
globalThis.__omnirouteCustomServerOwnsShutdown = previousCustomServerOwner;
}
}
});

View File

@@ -0,0 +1,132 @@
import assert from "node:assert/strict";
import { mkdtempSync, rmSync } from "node:fs";
import { tmpdir } from "node:os";
import { join } from "node:path";
import { pathToFileURL } from "node:url";
import test from "node:test";
import pino from "pino";
type LoggerModule = typeof import("../../src/shared/utils/logger.ts");
type LoggerResourceModule = typeof import("../../src/shared/utils/loggerResource.ts");
type LogRotationModule = typeof import("../../src/lib/logRotation.ts");
const loggerUrl = pathToFileURL(join(process.cwd(), "src/shared/utils/logger.ts")).href;
const loggerResourceUrl = pathToFileURL(
join(process.cwd(), "src/shared/utils/loggerResource.ts")
).href;
const logRotationUrl = pathToFileURL(join(process.cwd(), "src/lib/logRotation.ts")).href;
const envKeys = [
"NODE_ENV",
"APP_LOG_TO_FILE",
"APP_LOG_FILE_PATH",
"APP_LOG_LEVEL",
"APP_LOG_ROTATION_CHECK_INTERVAL_MS",
] as const;
function saveEnv(): Record<(typeof envKeys)[number], string | undefined> {
return Object.fromEntries(envKeys.map((key) => [key, process.env[key]])) as Record<
(typeof envKeys)[number],
string | undefined
>;
}
function restoreEnv(saved: ReturnType<typeof saveEnv>): void {
for (const key of envKeys) {
const value = saved[key];
if (value === undefined) delete process.env[key];
else process.env[key] = value;
}
}
function closeLoggerStream(logger: LoggerModule["logger"]): void {
const stream = (logger as unknown as Record<symbol, unknown>)[pino.symbols.streamSym] as
{ flushSync?: () => void; end?: () => void } | undefined;
try {
stream?.flushSync?.();
} catch {}
try {
stream?.end?.();
} catch {}
}
test("logger transport and rotation timer remain process-singletons across HMR module instances", async () => {
const savedEnv = saveEnv();
const testDir = mkdtempSync(join(tmpdir(), "omniroute-logger-singleton-12074-"));
const originalSetInterval = globalThis.setInterval;
let firstLogger: LoggerModule | undefined;
let secondLogger: LoggerModule | undefined;
let firstLoggerResource: LoggerResourceModule | undefined;
let secondLoggerResource: LoggerResourceModule | undefined;
let firstRotation: LogRotationModule | undefined;
let secondRotation: LogRotationModule | undefined;
process.env.NODE_ENV = "production";
process.env.APP_LOG_TO_FILE = "true";
process.env.APP_LOG_FILE_PATH = join(testDir, "application.log");
process.env.APP_LOG_LEVEL = "debug";
process.env.APP_LOG_ROTATION_CHECK_INTERVAL_MS = "60000";
try {
firstRotation = (await import(`${logRotationUrl}?phase4=rotation-a`)) as LogRotationModule;
secondRotation = (await import(`${logRotationUrl}?phase4=rotation-b`)) as LogRotationModule;
firstRotation.closeLogRotation();
secondRotation.closeLogRotation();
let intervalCreations = 0;
globalThis.setInterval = ((...args: unknown[]) => {
intervalCreations++;
return Reflect.apply(originalSetInterval, globalThis, args);
}) as typeof setInterval;
firstRotation.initLogRotation();
secondRotation.initLogRotation();
assert.equal(intervalCreations, 1, "HMR reloads must share one log rotation timer");
globalThis.setInterval = originalSetInterval;
firstLoggerResource = (await import(
`${loggerResourceUrl}?phase4=resource-a`
)) as LoggerResourceModule;
secondLoggerResource = (await import(
`${loggerResourceUrl}?phase4=resource-b`
)) as LoggerResourceModule;
firstLogger = (await import(`${loggerUrl}?phase4=logger-a`)) as LoggerModule;
secondLogger = (await import(`${loggerUrl}?phase4=logger-b`)) as LoggerModule;
assert.equal(firstLogger.logger, secondLogger.logger, "HMR reloads must reuse one logger");
const firstStream = (firstLogger.logger as unknown as Record<symbol, unknown>)[
pino.symbols.streamSym
];
const secondStream = (secondLogger.logger as unknown as Record<symbol, unknown>)[
pino.symbols.streamSym
];
assert.equal(firstStream, secondStream, "HMR reloads must reuse one pino transport");
const resource = globalThis.__omnirouteLoggerResource;
assert.ok(resource, "expected the process-wide logger resource to be registered");
const originalClose = resource.close;
let closeCalls = 0;
resource.close = async () => {
closeCalls++;
await originalClose();
};
await firstLoggerResource.closeSharedLoggerResource();
await secondLoggerResource.closeSharedLoggerResource();
assert.equal(closeCalls, 1, "shared logger teardown must be idempotent across HMR modules");
assert.equal(globalThis.__omnirouteLoggerResource, undefined);
} finally {
globalThis.setInterval = originalSetInterval;
firstRotation?.closeLogRotation();
secondRotation?.closeLogRotation();
if (firstLoggerResource) {
await firstLoggerResource.closeSharedLoggerResource();
} else {
if (firstLogger) closeLoggerStream(firstLogger.logger);
if (secondLogger && secondLogger.logger !== firstLogger?.logger) {
closeLoggerStream(secondLogger.logger);
}
}
restoreEnv(savedEnv);
rmSync(testDir, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 });
}
});

View File

@@ -0,0 +1,29 @@
import assert from "node:assert/strict";
import { readFileSync } from "node:fs";
import { join } from "node:path";
import test from "node:test";
const runNextSource = readFileSync(join(process.cwd(), "scripts/dev/run-next.mjs"), "utf8");
test("the custom Next runner owns exit and awaits application cleanup before closing Next", () => {
const ownerRegistration = runNextSource.indexOf(
"globalThis.__omnirouteCustomServerOwnsShutdown = true"
);
const prepareCall = runNextSource.indexOf("await prepareWithHeal()");
assert.ok(ownerRegistration >= 0, "custom server shutdown ownership must be registered");
assert.ok(
ownerRegistration < prepareCall,
"shutdown ownership must exist before instrumentation"
);
const serverClose = runNextSource.indexOf("server.close(resolve)");
const applicationCleanup = runNextSource.indexOf(
"await globalThis.__omnirouteRequestShutdown?.(signal)"
);
const nextClose = runNextSource.indexOf("await nextApp.close()", applicationCleanup);
const processExit = runNextSource.indexOf("process.exit(0)", nextClose);
assert.ok(serverClose < applicationCleanup, "stop accepting requests before application cleanup");
assert.ok(applicationCleanup < nextClose, "application cleanup must finish before Next closes");
assert.ok(nextClose < processExit, "process exit must remain the final shutdown action");
});