Logging: harden probe suppression for observations

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);
+  });
 });

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<string, unknown>;
+}): 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<LogObj>,
   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);