diff --git a/src/logging/subsystem.test.ts b/src/logging/subsystem.test.ts index e389d78ba8a..06f504f47de 100644 --- a/src/logging/subsystem.test.ts +++ b/src/logging/subsystem.test.ts @@ -1,11 +1,13 @@ -import { afterEach, describe, expect, it } from "vitest"; +import { afterEach, describe, expect, it, vi } from "vitest"; import { setConsoleSubsystemFilter } from "./console.js"; import { resetLogger, setLoggerOverride } from "./logger.js"; +import { loggingState } from "./state.js"; import { createSubsystemLogger } from "./subsystem.js"; afterEach(() => { setConsoleSubsystemFilter(null); setLoggerOverride(null); + loggingState.rawConsole = null; resetLogger(); }); @@ -53,4 +55,118 @@ describe("createSubsystemLogger().isEnabled", () => { expect(log.isEnabled("info", "file")).toBe(true); expect(log.isEnabled("info")).toBe(true); }); + + it("suppresses probe warnings for embedded subsystems based on structured run metadata", () => { + setLoggerOverride({ level: "silent", consoleLevel: "warn" }); + const warn = vi.fn(); + loggingState.rawConsole = { + log: vi.fn(), + info: vi.fn(), + warn, + error: vi.fn(), + }; + 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("does not suppress probe errors for embedded subsystems", () => { + setLoggerOverride({ level: "silent", consoleLevel: "error" }); + const error = vi.fn(); + loggingState.rawConsole = { + log: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + 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 = vi.fn(); + loggingState.rawConsole = { + log: vi.fn(), + info: vi.fn(), + warn, + error: vi.fn(), + }; + 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 = vi.fn(); + loggingState.rawConsole = { + log: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + 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 = vi.fn(); + loggingState.rawConsole = { + log: vi.fn(), + info: vi.fn(), + warn, + error: vi.fn(), + }; + 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 = vi.fn(); + loggingState.rawConsole = { + log: vi.fn(), + info: vi.fn(), + warn, + error: vi.fn(), + }; + const log = createSubsystemLogger("model-fallback").child("decision"); + + log.warn("model fallback decision", { + runId: "run-123", + consoleMessage: "model fallback decision", + }); + + expect(warn).toHaveBeenCalledTimes(1); + }); }); diff --git a/src/logging/subsystem.ts b/src/logging/subsystem.ts index 18be000e9ba..5c6ce58a43d 100644 --- a/src/logging/subsystem.ts +++ b/src/logging/subsystem.ts @@ -250,6 +250,38 @@ function writeConsoleLine(level: LogLevel, line: string) { } } +function shouldSuppressProbeConsoleLine(params: { + level: LogLevel; + subsystem: string; + message: string; + meta?: Record; +}): boolean { + if (isVerbose()) { + return false; + } + if (params.level === "error" || params.level === "fatal") { + return false; + } + const isProbeSuppressedSubsystem = + params.subsystem === "agent/embedded" || + params.subsystem.startsWith("agent/embedded/") || + params.subsystem === "model-fallback" || + params.subsystem.startsWith("model-fallback/"); + if (!isProbeSuppressedSubsystem) { + return false; + } + const runLikeId = + typeof params.meta?.runId === "string" + ? params.meta.runId + : typeof params.meta?.sessionId === "string" + ? params.meta.sessionId + : undefined; + if (runLikeId?.startsWith("probe-")) { + return true; + } + return /(sessionId|runId)=probe-/.test(params.message); +} + function logToFile( fileLogger: TsLogger, level: LogLevel, @@ -309,9 +341,12 @@ export function createSubsystemLogger(subsystem: string): SubsystemLogger { } const consoleMessage = consoleMessageOverride ?? message; if ( - !isVerbose() && - subsystem === "agent/embedded" && - /(sessionId|runId)=probe-/.test(consoleMessage) + shouldSuppressProbeConsoleLine({ + level, + subsystem, + message: consoleMessage, + meta: fileMeta, + }) ) { return; } @@ -355,11 +390,7 @@ export function createSubsystemLogger(subsystem: string): SubsystemLogger { logToFile(getFileLogger(), "info", message, { raw: true }); } if (isConsoleEnabled("info")) { - if ( - !isVerbose() && - subsystem === "agent/embedded" && - /(sessionId|runId)=probe-/.test(message) - ) { + if (shouldSuppressProbeConsoleLine({ level: "info", subsystem, message })) { return; } writeConsoleLine("info", message);