Logging: harden probe suppression for observations (#41338)
Merged via squash. Prepared head SHA: d18356cb8062935090466d4e142ce202381d4ef2 Co-authored-by: altaywtf <9790196+altaywtf@users.noreply.github.com> Co-authored-by: altaywtf <9790196+altaywtf@users.noreply.github.com> Reviewed-by: @altaywtf
This commit is contained in:
parent
64746c150c
commit
de4c3db3e3
@ -37,6 +37,7 @@ Docs: https://docs.openclaw.ai
|
||||
- Agents/fallback observability: add structured, sanitized model-fallback decision and auth-profile failure-state events with correlated run IDs so cooldown probes and failover paths are easier to trace in logs. (#41337) thanks @altaywtf.
|
||||
- Protocol/Swift model sync: regenerate pending node work Swift bindings after the landed `node.pending.*` schema additions so generated protocol artifacts are consistent again. (#41477) Thanks @mbelinky.
|
||||
- Discord/reply chunking: resolve the effective `maxLinesPerMessage` config across live reply paths and preserve `chunkMode` in the fast send path so long Discord replies no longer split unexpectedly at the default 17-line limit. (#40133) thanks @rbutera.
|
||||
- Logging/probe observations: suppress structured embedded and model-fallback probe warnings on the console without hiding error or fatal output. (#41338) thanks @altaywtf.
|
||||
|
||||
## 2026.3.8
|
||||
|
||||
|
||||
@ -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);
|
||||
});
|
||||
});
|
||||
|
||||
@ -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);
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user