From 842087319b30e6baef5b11677b9a187c070aaf1e Mon Sep 17 00:00:00 2001 From: Peter Steinberger Date: Mon, 2 Mar 2026 18:41:08 +0000 Subject: [PATCH] perf(logging): skip config/fs work in default silent test path --- src/logging/console-settings.test.ts | 8 ++++ src/logging/console.ts | 14 +++++- src/logging/logger-settings.test.ts | 66 ++++++++++++++++++++++++++++ src/logging/logger.ts | 40 ++++++++++++++--- 4 files changed, 121 insertions(+), 7 deletions(-) create mode 100644 src/logging/logger-settings.test.ts diff --git a/src/logging/console-settings.test.ts b/src/logging/console-settings.test.ts index 905aea21d..6431b67c8 100644 --- a/src/logging/console-settings.test.ts +++ b/src/logging/console-settings.test.ts @@ -26,6 +26,7 @@ type ConsoleSnapshot = { }; let originalIsTty: boolean | undefined; +let originalOpenClawTestConsole: string | undefined; let snapshot: ConsoleSnapshot; let logging: typeof import("../logging.js"); let state: typeof import("./state.js"); @@ -46,6 +47,8 @@ beforeEach(() => { trace: console.trace, }; originalIsTty = process.stdout.isTTY; + originalOpenClawTestConsole = process.env.OPENCLAW_TEST_CONSOLE; + process.env.OPENCLAW_TEST_CONSOLE = "1"; Object.defineProperty(process.stdout, "isTTY", { value: false, configurable: true }); }); @@ -56,6 +59,11 @@ afterEach(() => { console.error = snapshot.error; console.debug = snapshot.debug; console.trace = snapshot.trace; + if (originalOpenClawTestConsole === undefined) { + delete process.env.OPENCLAW_TEST_CONSOLE; + } else { + process.env.OPENCLAW_TEST_CONSOLE = originalOpenClawTestConsole; + } Object.defineProperty(process.stdout, "isTTY", { value: originalIsTty, configurable: true }); logging.setConsoleConfigLoaderForTests(); vi.restoreAllMocks(); diff --git a/src/logging/console.ts b/src/logging/console.ts index b2b259565..c1970def5 100644 --- a/src/logging/console.ts +++ b/src/logging/console.ts @@ -58,6 +58,19 @@ function normalizeConsoleStyle(style?: string): ConsoleStyle { } function resolveConsoleSettings(): ConsoleSettings { + const envLevel = resolveEnvLogLevelOverride(); + // Test runs default to silent console logging unless explicitly overridden. + // Skip config-file and full config fallback reads in this fast path. + if ( + process.env.VITEST === "true" && + process.env.OPENCLAW_TEST_CONSOLE !== "1" && + !isVerbose() && + !envLevel && + !loggingState.overrideSettings + ) { + return { level: "silent", style: normalizeConsoleStyle(undefined) }; + } + let cfg: OpenClawConfig["logging"] | undefined = (loggingState.overrideSettings as LoggerSettings | null) ?? readLoggingConfig(); if (!cfg) { @@ -72,7 +85,6 @@ function resolveConsoleSettings(): ConsoleSettings { } } } - const envLevel = resolveEnvLogLevelOverride(); const level = envLevel ?? normalizeConsoleLevel(cfg?.consoleLevel); const style = normalizeConsoleStyle(cfg?.consoleStyle); return { level, style }; diff --git a/src/logging/logger-settings.test.ts b/src/logging/logger-settings.test.ts new file mode 100644 index 000000000..89aaedd22 --- /dev/null +++ b/src/logging/logger-settings.test.ts @@ -0,0 +1,66 @@ +import { afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; + +const { fallbackRequireMock, readLoggingConfigMock } = vi.hoisted(() => ({ + readLoggingConfigMock: vi.fn(() => undefined), + fallbackRequireMock: vi.fn(() => { + throw new Error("config fallback should not be used in this test"); + }), +})); + +vi.mock("./config.js", () => ({ + readLoggingConfig: readLoggingConfigMock, +})); + +vi.mock("./node-require.js", () => ({ + resolveNodeRequireFromMeta: () => fallbackRequireMock, +})); + +let originalTestFileLog: string | undefined; +let originalOpenClawLogLevel: string | undefined; +let logging: typeof import("../logging.js"); + +beforeAll(async () => { + logging = await import("../logging.js"); +}); + +beforeEach(() => { + originalTestFileLog = process.env.OPENCLAW_TEST_FILE_LOG; + originalOpenClawLogLevel = process.env.OPENCLAW_LOG_LEVEL; + delete process.env.OPENCLAW_TEST_FILE_LOG; + delete process.env.OPENCLAW_LOG_LEVEL; + readLoggingConfigMock.mockClear(); + fallbackRequireMock.mockClear(); + logging.resetLogger(); + logging.setLoggerOverride(null); +}); + +afterEach(() => { + if (originalTestFileLog === undefined) { + delete process.env.OPENCLAW_TEST_FILE_LOG; + } else { + process.env.OPENCLAW_TEST_FILE_LOG = originalTestFileLog; + } + if (originalOpenClawLogLevel === undefined) { + delete process.env.OPENCLAW_LOG_LEVEL; + } else { + process.env.OPENCLAW_LOG_LEVEL = originalOpenClawLogLevel; + } + logging.resetLogger(); + logging.setLoggerOverride(null); + vi.restoreAllMocks(); +}); + +describe("getResolvedLoggerSettings", () => { + it("uses a silent fast path in default Vitest mode without config reads", () => { + const settings = logging.getResolvedLoggerSettings(); + expect(settings.level).toBe("silent"); + expect(readLoggingConfigMock).not.toHaveBeenCalled(); + expect(fallbackRequireMock).not.toHaveBeenCalled(); + }); + + it("reads logging config when test file logging is explicitly enabled", () => { + process.env.OPENCLAW_TEST_FILE_LOG = "1"; + const settings = logging.getResolvedLoggerSettings(); + expect(settings.level).toBe("info"); + }); +}); diff --git a/src/logging/logger.ts b/src/logging/logger.ts index 074058051..dcb89de9a 100644 --- a/src/logging/logger.ts +++ b/src/logging/logger.ts @@ -55,7 +55,27 @@ function attachExternalTransport(logger: TsLogger, transport: LogTranspo }); } +function canUseSilentVitestFileLogFastPath(envLevel: LogLevel | undefined): boolean { + return ( + process.env.VITEST === "true" && + process.env.OPENCLAW_TEST_FILE_LOG !== "1" && + !envLevel && + !loggingState.overrideSettings + ); +} + function resolveSettings(): ResolvedSettings { + const envLevel = resolveEnvLogLevelOverride(); + // Test runs default file logs to silent. Skip config reads and fallback load in the + // common case to avoid pulling heavy config/schema stacks on startup. + if (canUseSilentVitestFileLogFastPath(envLevel)) { + return { + level: "silent", + file: defaultRollingPathForToday(), + maxFileBytes: DEFAULT_MAX_LOG_FILE_BYTES, + }; + } + let cfg: OpenClawConfig["logging"] | undefined = (loggingState.overrideSettings as LoggerSettings | null) ?? readLoggingConfig(); if (!cfg) { @@ -73,7 +93,6 @@ function resolveSettings(): ResolvedSettings { const defaultLevel = process.env.VITEST === "true" && process.env.OPENCLAW_TEST_FILE_LOG !== "1" ? "silent" : "info"; const fromConfig = normalizeLogLevel(cfg?.level, defaultLevel); - const envLevel = resolveEnvLogLevelOverride(); const level = envLevel ?? fromConfig; const file = cfg?.file ?? defaultRollingPathForToday(); const maxFileBytes = resolveMaxLogFileBytes(cfg?.maxFileBytes); @@ -99,6 +118,20 @@ export function isFileLogLevelEnabled(level: LogLevel): boolean { } function buildLogger(settings: ResolvedSettings): TsLogger { + const logger = new TsLogger({ + name: "openclaw", + minLevel: levelToMinLevel(settings.level), + type: "hidden", // no ansi formatting + }); + + // Silent logging does not write files; skip all filesystem setup in this path. + if (settings.level === "silent") { + for (const transport of externalTransports) { + attachExternalTransport(logger, transport); + } + return logger; + } + fs.mkdirSync(path.dirname(settings.file), { recursive: true }); // Clean up stale rolling logs when using a dated log filename. if (isRollingPath(settings.file)) { @@ -106,11 +139,6 @@ function buildLogger(settings: ResolvedSettings): TsLogger { } let currentFileBytes = getCurrentLogFileBytes(settings.file); let warnedAboutSizeCap = false; - const logger = new TsLogger({ - name: "openclaw", - minLevel: levelToMinLevel(settings.level), - type: "hidden", // no ansi formatting - }); logger.attachTransport((logObj: LogObj) => { try {