// Subsystem logger tests cover per-subsystem log routing and filtering. import fs from "node:fs"; import path from "node:path"; import { Logger as TsLogger } from "tslog"; import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest"; import { setConsoleSubsystemFilter, shouldLogSubsystemToConsole } from "./console.js"; import { createSuiteLogPathTracker } from "./log-test-helpers.js"; import { applyLoggingConfig, resetLogger, setLoggerOverride } from "./logger.js"; import { testApi } from "./logger.test-support.js"; import { loggingState } from "./state.js"; import { createSubsystemLogger } from "./subsystem.js"; const logPathTracker = createSuiteLogPathTracker("openclaw-subsystem-log-"); function installConsoleMethodSpy(method: "log" | "warn" | "error") { const spy = vi.fn(); loggingState.rawConsole = { log: method === "log" ? spy : vi.fn(), info: vi.fn(), warn: method === "warn" ? spy : vi.fn(), error: method === "error" ? spy : vi.fn(), }; return spy; } function firstMockArgAsString(mock: { mock: { calls: readonly unknown[][] } }): string { const [call] = mock.mock.calls; if (!call) { throw new Error("expected console mock call"); } return String(call[0]); } beforeAll(async () => { await logPathTracker.setup(); }); afterEach(() => { setConsoleSubsystemFilter(null); setLoggerOverride(null); loggingState.rawConsole = null; resetLogger(); vi.unstubAllEnvs(); vi.restoreAllMocks(); vi.useRealTimers(); }); afterAll(async () => { await logPathTracker.cleanup(); }); describe("createSubsystemLogger().isEnabled", () => { it("returns true for any/file when only file logging would emit", () => { setLoggerOverride({ level: "debug", consoleLevel: "silent" }); const log = createSubsystemLogger("agent/embedded"); expect(log.isEnabled("debug")).toBe(true); expect(log.isEnabled("debug", "file")).toBe(true); expect(log.isEnabled("debug", "console")).toBe(false); }); it("returns true for any/console when only console logging would emit", () => { setLoggerOverride({ level: "silent", consoleLevel: "debug" }); const log = createSubsystemLogger("agent/embedded"); expect(log.isEnabled("debug")).toBe(true); expect(log.isEnabled("debug", "console")).toBe(true); expect(log.isEnabled("debug", "file")).toBe(false); }); it("uses threshold ordering for non-equal console levels", () => { setLoggerOverride({ level: "silent", consoleLevel: "fatal" }); const fatalOnly = createSubsystemLogger("agent/embedded"); expect(fatalOnly.isEnabled("error", "console")).toBe(false); expect(fatalOnly.isEnabled("fatal", "console")).toBe(true); setLoggerOverride({ level: "silent", consoleLevel: "trace" }); const traceLogger = createSubsystemLogger("agent/embedded"); expect(traceLogger.isEnabled("debug", "console")).toBe(true); }); it("never treats silent as an emittable console level", () => { setLoggerOverride({ level: "silent", consoleLevel: "info" }); const log = createSubsystemLogger("agent/embedded"); expect(log.isEnabled("silent", "console")).toBe(false); }); it("returns false when neither console nor file logging would emit", () => { setLoggerOverride({ level: "silent", consoleLevel: "silent" }); const log = createSubsystemLogger("agent/embedded"); expect(log.isEnabled("debug")).toBe(false); expect(log.isEnabled("debug", "console")).toBe(false); expect(log.isEnabled("debug", "file")).toBe(false); }); it("honors console subsystem filters for console target", () => { setLoggerOverride({ level: "silent", consoleLevel: "info" }); setConsoleSubsystemFilter(["gateway"]); const log = createSubsystemLogger("agent/embedded"); expect(log.isEnabled("info", "console")).toBe(false); }); it("does not apply console subsystem filters to file target", () => { setLoggerOverride({ level: "info", consoleLevel: "silent" }); setConsoleSubsystemFilter(["gateway"]); const log = createSubsystemLogger("agent/embedded"); expect(log.isEnabled("info", "file")).toBe(true); expect(log.isEnabled("info")).toBe(true); }); it("treats missing subsystem labels as non-matches when filters are active", () => { setConsoleSubsystemFilter(["gateway"]); expect(shouldLogSubsystemToConsole(undefined as unknown as string)).toBe(false); }); it("disables console logging when a malformed subsystem logger checks enablement", () => { setLoggerOverride({ level: "silent", consoleLevel: "info" }); setConsoleSubsystemFilter(["gateway"]); const log = createSubsystemLogger(undefined as unknown as string); expect(log.isEnabled("info", "console")).toBe(false); }); it("falls back to an unknown subsystem label when a malformed logger emits", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn" }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger(undefined as unknown as string); log.warn("missing subsystem label"); expect(warn).toHaveBeenCalledTimes(1); expect(firstMockArgAsString(warn)).toContain("[unknown]"); }); it("suppresses probe warnings for embedded subsystems based on structured run metadata", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn" }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger("agent/embedded").child("failover"); log.warn("embedded run failover decision", { runId: "probe-test-run", consoleMessage: "embedded run failover decision", }); expect(warn).not.toHaveBeenCalled(); }); it("keeps setup-inference probe warnings in the file log while suppressing console", async () => { const file = logPathTracker.nextPath(); setLoggerOverride({ level: "warn", consoleLevel: "warn", file }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger("agent/embedded"); log.warn("embedded run failover decision", { runId: "probe-setup-inference-test-run", provider: "openai", consoleMessage: "embedded run failover decision: provider=openai error=Authentication failed", }); log.warn("embedded run agent end", { runId: "probe-setup-inference-test-run", provider: "openai", consoleMessage: "embedded run agent end: provider=openai error=Authentication failed", }); expect(warn).not.toHaveBeenCalled(); await testApi.flushFileLogQueueForTests(); const fileLog = fs.readFileSync(file, "utf8"); expect(fileLog).toContain("embedded run failover decision"); expect(fileLog).toContain("embedded run agent end"); expect(fileLog).toContain('"provider":"openai"'); }); it("does not suppress probe errors for embedded subsystems", () => { setLoggerOverride({ level: "silent", consoleLevel: "error" }); const error = installConsoleMethodSpy("error"); const log = createSubsystemLogger("agent/embedded").child("failover"); log.error("embedded run failover decision", { runId: "probe-test-run", consoleMessage: "embedded run failover decision", }); expect(error).toHaveBeenCalledTimes(1); }); it("suppresses probe warnings for model-fallback child subsystems based on structured run metadata", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn" }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger("model-fallback").child("decision"); log.warn("model fallback decision", { runId: "probe-test-run", consoleMessage: "model fallback decision", }); expect(warn).not.toHaveBeenCalled(); }); it("does not suppress probe errors for model-fallback child subsystems", () => { setLoggerOverride({ level: "silent", consoleLevel: "error" }); const error = installConsoleMethodSpy("error"); const log = createSubsystemLogger("model-fallback").child("decision"); log.error("model fallback decision", { runId: "probe-test-run", consoleMessage: "model fallback decision", }); expect(error).toHaveBeenCalledTimes(1); }); it("still emits non-probe warnings for embedded subsystems", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn" }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger("agent/embedded").child("auth-profiles"); log.warn("auth profile failure state updated", { runId: "run-123", consoleMessage: "auth profile failure state updated", }); expect(warn).toHaveBeenCalledTimes(1); }); it("still emits non-probe model-fallback child warnings", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn" }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger("model-fallback").child("decision"); log.warn("model fallback decision", { runId: "run-123", consoleMessage: "model fallback decision", }); expect(warn).toHaveBeenCalledTimes(1); }); it("redacts sensitive tokens at the console sink so subsystem writes do not leak secrets (#73284)", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn" }); const warn = installConsoleMethodSpy("warn"); const log = createSubsystemLogger("gateway"); const secret = "sk-supersecretvaluefortest12345"; log.warn(`token=${secret}`); expect(warn).toHaveBeenCalledTimes(1); const written = firstMockArgAsString(warn); expect(written).not.toContain(secret); expect(written).toMatch(/sk-sup…2345|\*\*\*/); }); it("redacts Bearer tokens on subsystem error console writes", () => { setLoggerOverride({ level: "silent", consoleLevel: "error" }); const error = installConsoleMethodSpy("error"); const log = createSubsystemLogger("gateway").child("auth"); const bearer = "Bearer abcdefghijklmnopqrstuvwxyz"; log.error(`Authorization failed: ${bearer}`); expect(error).toHaveBeenCalledTimes(1); const written = firstMockArgAsString(error); expect(written).not.toContain("abcdefghijklmnopqrstuvwxyz"); expect(written).toContain("Bearer "); }); it("redacts before colorizing subsystem console messages so ANSI reset codes survive", () => { vi.stubEnv("FORCE_COLOR", "1"); setLoggerOverride({ level: "silent", consoleLevel: "info" }); const logSpy = installConsoleMethodSpy("log"); const log = createSubsystemLogger("gateway/auth"); const secret = "sk-abcdefghijklmnopqrstuvwxyz123456"; log.info(`provider API_KEY=${secret}`); expect(logSpy).toHaveBeenCalledTimes(1); const written = firstMockArgAsString(logSpy); expect(written).not.toContain(secret); expect(written).toContain("API_KEY=***"); expect(written.endsWith("\u001B[39m")).toBe(true); }); it("redacts sensitive tokens from raw subsystem console output", () => { setLoggerOverride({ level: "silent", consoleLevel: "info" }); const logSpy = installConsoleMethodSpy("log"); const log = createSubsystemLogger("gateway/auth"); const secret = "sk-rawtokenabcdefghijklmnopqrstuvwxyz123456"; log.raw(`raw token ${secret}`); expect(logSpy).toHaveBeenCalledTimes(1); const written = firstMockArgAsString(logSpy); expect(written).not.toContain(secret); expect(written).toContain("sk-raw…3456"); }); it("wraps raw subsystem output when console style is JSON", () => { setLoggerOverride({ level: "silent", consoleLevel: "info", consoleStyle: "json" }); const logSpy = installConsoleMethodSpy("log"); createSubsystemLogger("gateway/auth").raw("raw diagnostic"); expect(logSpy).toHaveBeenCalledTimes(1); expect(JSON.parse(firstMockArgAsString(logSpy))).toMatchObject({ level: "info", subsystem: "gateway/auth", message: "raw diagnostic", }); }); it.each(["pretty", "compact"] as const)( "keeps raw subsystem output unchanged in %s style", (consoleStyle) => { setLoggerOverride({ level: "silent", consoleLevel: "info", consoleStyle }); const logSpy = installConsoleMethodSpy("log"); createSubsystemLogger("gateway/auth").raw("raw diagnostic"); expect(logSpy).toHaveBeenCalledWith("raw diagnostic"); }, ); it("preserves structured subsystem fields through the shared JSON formatter", () => { setLoggerOverride({ level: "silent", consoleLevel: "warn", consoleStyle: "json" }); const warn = installConsoleMethodSpy("warn"); createSubsystemLogger("gateway/auth").warn("authentication retry", { attempt: 2 }); expect(JSON.parse(firstMockArgAsString(warn))).toMatchObject({ level: "warn", subsystem: "gateway/auth", message: "authentication retry", attempt: 2, }); }); it("keeps long-lived subsystem loggers on the current-day rolling file", async () => { const logDir = path.dirname(logPathTracker.nextPath()); const firstDay = path.join(logDir, "openclaw-2026-01-01.log"); const secondDay = path.join(logDir, "openclaw-2026-01-02.log"); vi.useFakeTimers(); vi.setSystemTime(new Date("2026-01-01T08:00:00Z")); setLoggerOverride({ level: "info", consoleLevel: "silent", file: firstDay }); const log = createSubsystemLogger("diagnostics"); log.info("first day subsystem log"); vi.setSystemTime(new Date("2026-01-02T08:00:00Z")); log.info("second day subsystem log"); await testApi.flushFileLogQueueForTests(); expect(fs.readFileSync(firstDay, "utf8")).toContain("first day subsystem log"); expect(fs.readFileSync(secondDay, "utf8")).toContain("second day subsystem log"); expect(fs.readFileSync(firstDay, "utf8")).not.toContain("second day subsystem log"); }); it("reuses its file child until logger invalidation advances the generation", () => { const firstFile = logPathTracker.nextPath(); const secondFile = logPathTracker.nextPath(); const getSubLogger = vi.spyOn(TsLogger.prototype, "getSubLogger"); setLoggerOverride({ level: "info", consoleLevel: "silent", file: firstFile }); const log = createSubsystemLogger("diagnostics"); log.info("first line"); log.info("second line"); expect(getSubLogger).toHaveBeenCalledTimes(1); resetLogger(); setLoggerOverride({ level: "info", consoleLevel: "silent", file: secondFile }); log.info("after reset"); expect(getSubLogger).toHaveBeenCalledTimes(2); }); it("publishes applied config and rebuilds its child for the new generation", () => { const firstFile = logPathTracker.nextPath(); const secondFile = logPathTracker.nextPath(); vi.stubEnv("OPENCLAW_TEST_FILE_LOG", "1"); applyLoggingConfig({ level: "info", consoleLevel: "silent", file: firstFile }); const getSubLogger = vi.spyOn(TsLogger.prototype, "getSubLogger"); const log = createSubsystemLogger("diagnostics"); log.info("first line"); log.info("second line"); expect(getSubLogger).toHaveBeenCalledTimes(1); expect(log.isEnabled("debug", "file")).toBe(false); applyLoggingConfig({ level: "debug", consoleLevel: "silent", file: secondFile }); expect(log.isEnabled("debug", "file")).toBe(true); log.debug("after applied config"); expect(getSubLogger).toHaveBeenCalledTimes(2); }); });