fix(logging): keep log transport internals private (#71322)

* fix(logging): share transports across module instances

* fix(logging): share transports across module instances

* fix(logging): share transports across module instances

* fix(logging): remove global log transport hooks

* test(agents): capture diagnostic logs after module reset
This commit is contained in:
Vincent Koc
2026-04-24 23:36:57 -07:00
committed by GitHub
parent 6b38714cb9
commit 3d554aefdf
9 changed files with 128 additions and 96 deletions

View File

@@ -2,6 +2,7 @@ import os from "node:os";
import path from "node:path";
import { afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest";
import type { OpenClawConfig } from "../config/config.js";
import { createDiagnosticLogRecordCapture } from "../logging/test-helpers/diagnostic-log-capture.js";
import type { AuthProfileStore } from "./auth-profiles.js";
import { makeModelFallbackCfg } from "./test-helpers/model-fallback-config-fixture.js";
@@ -56,12 +57,11 @@ let mockedResolveAuthProfileOrder: ReturnType<
>;
let runWithModelFallback: ModelFallbackModule["runWithModelFallback"];
let _probeThrottleInternals: ModelFallbackModule["_probeThrottleInternals"];
let registerLogTransport: LoggerModule["registerLogTransport"];
let resetLogger: LoggerModule["resetLogger"];
let setLoggerOverride: LoggerModule["setLoggerOverride"];
const makeCfg = makeModelFallbackCfg;
let unregisterLogTransport: (() => void) | undefined;
let cleanupLogCapture: (() => void) | undefined;
async function loadModelFallbackProbeModules() {
const authProfilesStoreModule = await import("./auth-profiles/store.js");
@@ -82,7 +82,6 @@ async function loadModelFallbackProbeModules() {
mockedResolveAuthProfileOrder = vi.mocked(authProfilesOrderModule.resolveAuthProfileOrder);
runWithModelFallback = modelFallbackModule.runWithModelFallback;
_probeThrottleInternals = modelFallbackModule._probeThrottleInternals;
registerLogTransport = loggerModule.registerLogTransport;
resetLogger = loggerModule.resetLogger;
setLoggerOverride = loggerModule.setLoggerOverride;
}
@@ -236,8 +235,8 @@ describe("runWithModelFallback probe logic", () => {
afterEach(() => {
Date.now = realDateNow;
unregisterLogTransport?.();
unregisterLogTransport = undefined;
cleanupLogCapture?.();
cleanupLogCapture = undefined;
setLoggerOverride(null);
resetLogger();
vi.restoreAllMocks();
@@ -275,16 +274,14 @@ describe("runWithModelFallback probe logic", () => {
it("logs primary metadata on probe success and failure fallback decisions", async () => {
const cfg = makeCfg();
const records: Array<Record<string, unknown>> = [];
const logCapture = createDiagnosticLogRecordCapture();
cleanupLogCapture = logCapture.cleanup;
mockedGetSoonestCooldownExpiry.mockReturnValue(NOW + 60 * 1000);
setLoggerOverride({
level: "trace",
consoleLevel: "silent",
file: path.join(os.tmpdir(), `openclaw-model-fallback-probe-${Date.now()}.log`),
});
unregisterLogTransport = registerLogTransport((record) => {
records.push(record);
});
const run = vi.fn().mockResolvedValue("probed-ok");
@@ -311,6 +308,7 @@ describe("runWithModelFallback probe logic", () => {
.mockResolvedValueOnce("fallback-ok");
const fallbackResult = await runPrimaryCandidate(fallbackCfg, fallbackRun);
await logCapture.flush();
expect(fallbackResult.result).toBe("fallback-ok");
expect(fallbackRun).toHaveBeenNthCalledWith(1, "openai", "gpt-4.1-mini", {
@@ -318,14 +316,9 @@ describe("runWithModelFallback probe logic", () => {
});
expect(fallbackRun).toHaveBeenNthCalledWith(2, "anthropic", "claude-haiku-3-5");
const decisionPayloads = records
.filter(
(record) =>
record["2"] === "model fallback decision" &&
record["1"] &&
typeof record["1"] === "object",
)
.map((record) => record["1"] as Record<string, unknown>);
const decisionPayloads = logCapture.records
.filter((record) => record.message === "model fallback decision")
.map((record) => record.attributes ?? {});
expect(decisionPayloads).toEqual(
expect.arrayContaining([

View File

@@ -1014,7 +1014,7 @@ describe("runWithModelFallback", () => {
});
expect(result.result).toBe("ok");
const warning = warnLogs.findText('Model "openai/gpt-6spoof" not found');
const warning = await warnLogs.findText('Model "openai/gpt-6spoof" not found');
expect(warning).toContain('Model "openai/gpt-6spoof" not found');
expect(warning).not.toContain("\u001B");
expect(warning).not.toContain("\n");

View File

@@ -966,7 +966,7 @@ describe("model-selection", () => {
}
});
it("sanitizes control characters in providerless-model warnings", () => {
it("sanitizes control characters in providerless-model warnings", async () => {
const warnLogs = createWarnLogCapture("openclaw-model-selection-test");
try {
const cfg: Partial<OpenClawConfig> = {
@@ -987,7 +987,7 @@ describe("model-selection", () => {
provider: "google",
model: "\u001B[31mclaude-3-5-sonnet\nspoof",
});
const warning = warnLogs.findText('Falling back to "google/claude-3-5-sonnet"');
const warning = await warnLogs.findText('Falling back to "google/claude-3-5-sonnet"');
expect(warning).toContain('Falling back to "google/claude-3-5-sonnet"');
expect(warning).not.toContain("\u001B");
expect(warning).not.toContain("\n");

View File

@@ -106,8 +106,8 @@ const installRunEmbeddedMocks = () => {
};
let runEmbeddedPiAgent: typeof import("./pi-embedded-runner/run.js").runEmbeddedPiAgent;
let unregisterLogTransport: (() => void) | undefined;
let registerLogTransportFn: typeof import("../logging/logger.js").registerLogTransport;
let createDiagnosticLogRecordCaptureFn: typeof import("../logging/test-helpers/diagnostic-log-capture.js").createDiagnosticLogRecordCapture;
let cleanupLogCapture: (() => void) | undefined;
let resetLoggerFn: typeof import("../logging/logger.js").resetLogger;
let setLoggerOverrideFn: typeof import("../logging/logger.js").setLoggerOverride;
const originalFetch = globalThis.fetch;
@@ -116,11 +116,10 @@ beforeAll(async () => {
vi.resetModules();
installRunEmbeddedMocks();
({ runEmbeddedPiAgent } = await import("./pi-embedded-runner/run.js"));
({
registerLogTransport: registerLogTransportFn,
resetLogger: resetLoggerFn,
setLoggerOverride: setLoggerOverrideFn,
} = await import("../logging/logger.js"));
({ createDiagnosticLogRecordCapture: createDiagnosticLogRecordCaptureFn } =
await import("../logging/test-helpers/diagnostic-log-capture.js"));
({ resetLogger: resetLoggerFn, setLoggerOverride: setLoggerOverrideFn } =
await import("../logging/logger.js"));
});
async function runEmbeddedPiAgentInline(
@@ -152,8 +151,8 @@ beforeEach(() => {
afterEach(() => {
globalThis.fetch = originalFetch;
unregisterLogTransport?.();
unregisterLogTransport = undefined;
cleanupLogCapture?.();
cleanupLogCapture = undefined;
setLoggerOverrideFn(null);
resetLoggerFn();
});
@@ -864,15 +863,13 @@ describe("runEmbeddedPiAgent auth profile rotation", () => {
});
it("logs structured failover decision metadata for overloaded assistant rotation", async () => {
const records: Array<Record<string, unknown>> = [];
const logCapture = createDiagnosticLogRecordCaptureFn();
cleanupLogCapture = logCapture.cleanup;
setLoggerOverrideFn({
level: "trace",
consoleLevel: "silent",
file: path.join(os.tmpdir(), `openclaw-auth-rotation-${Date.now()}.log`),
});
unregisterLogTransport = registerLogTransportFn((record) => {
records.push(record);
});
await runAutoPinnedRotationCase({
errorMessage:
@@ -880,18 +877,17 @@ describe("runEmbeddedPiAgent auth profile rotation", () => {
sessionKey: "agent:test:overloaded-logging",
runId: "run:overloaded-logging",
});
await logCapture.flush();
const decisionRecord = records.find(
const decisionRecord = logCapture.records.find(
(record) =>
record["2"] === "embedded run failover decision" &&
record["1"] &&
typeof record["1"] === "object" &&
(record["1"] as Record<string, unknown>).decision === "rotate_profile",
record.message === "embedded run failover decision" &&
record.attributes?.decision === "rotate_profile",
);
expect(decisionRecord).toBeDefined();
const safeProfileId = redactIdentifier("openai:p1", { len: 12 });
expect((decisionRecord as Record<string, unknown>)["1"]).toMatchObject({
expect(decisionRecord?.attributes).toMatchObject({
event: "embedded_run_failover_decision",
runId: "run:overloaded-logging",
decision: "rotate_profile",
@@ -903,16 +899,14 @@ describe("runEmbeddedPiAgent auth profile rotation", () => {
rawErrorPreview: expect.stringContaining('"request_id":"sha256:'),
});
const stateRecord = records.find(
const stateRecord = logCapture.records.find(
(record) =>
record["2"] === "auth profile failure state updated" &&
record["1"] &&
typeof record["1"] === "object" &&
(record["1"] as Record<string, unknown>).profileId === safeProfileId,
record.message === "auth profile failure state updated" &&
record.attributes?.profileId === safeProfileId,
);
expect(stateRecord).toBeDefined();
expect((stateRecord as Record<string, unknown>)["1"]).toMatchObject({
expect(stateRecord?.attributes).toMatchObject({
event: "auth_profile_failure_state_updated",
runId: "run:overloaded-logging",
profileId: safeProfileId,

View File

@@ -0,0 +1,60 @@
import { afterAll, afterEach, beforeAll, describe, expect, it } from "vitest";
import { importFreshModule } from "../../test/helpers/import-fresh.js";
import { createSuiteLogPathTracker } from "./log-test-helpers.js";
type LoggerModule = typeof import("./logger.js");
const logPathTracker = createSuiteLogPathTracker("openclaw-logger-transport-");
const importedModules: LoggerModule[] = [];
async function importLoggerModule(scope: string): Promise<LoggerModule> {
const module = await importFreshModule<LoggerModule>(
import.meta.url,
`./logger.js?scope=${scope}`,
);
importedModules.push(module);
module.setLoggerOverride({
level: "info",
file: logPathTracker.nextPath(),
});
return module;
}
describe("logger transport registry", () => {
beforeAll(async () => {
await logPathTracker.setup();
});
afterEach(() => {
while (importedModules.length > 0) {
const module = importedModules.pop();
module?.resetLogger();
module?.setLoggerOverride(null);
}
});
afterAll(async () => {
await logPathTracker.cleanup();
});
it("does not expose production or test log transport registration", async () => {
const loggerModule = await importLoggerModule("public-api");
expect(
(loggerModule as unknown as Record<string, unknown>).registerLogTransport,
).toBeUndefined();
expect(
(loggerModule.__test__ as unknown as Record<string, unknown>).registerLogTransportForTest,
).toBeUndefined();
});
it("does not publish mutable log transport state on a well-known global symbol", async () => {
await importLoggerModule("global-state");
expect(
(globalThis as typeof globalThis & Record<PropertyKey, unknown>)[
Symbol.for("openclaw.logging.transports")
],
).toBeUndefined();
});
});

View File

@@ -68,10 +68,7 @@ type ResolvedSettings = {
maxFileBytes: number;
};
export type LoggerResolvedSettings = ResolvedSettings;
export type LogTransportRecord = Record<string, unknown>;
export type LogTransport = (logObj: LogTransportRecord) => void;
const externalTransports = new Set<LogTransport>();
type TsLogRecord = Record<string, unknown>;
type DiagnosticLogCode = {
line?: number;
@@ -87,19 +84,6 @@ const DIAGNOSTIC_LOG_ATTRIBUTE_KEY_RE = /^[A-Za-z0-9_.:-]{1,64}$/u;
type DiagnosticLogAttributes = Record<string, string | number | boolean>;
function attachExternalTransport(logger: TsLogger<LogObj>, transport: LogTransport): void {
logger.attachTransport((logObj: LogObj) => {
if (!externalTransports.has(transport)) {
return;
}
try {
transport(logObj as LogTransportRecord);
} catch {
// never block on logging failures
}
});
}
function clampDiagnosticLogText(value: string, maxChars: number): string {
return value.length > maxChars ? `${value.slice(0, maxChars)}...(truncated)` : value;
}
@@ -237,7 +221,7 @@ function findLogTraceContext(
return undefined;
}
function buildDiagnosticLogRecord(logObj: LogTransportRecord) {
function buildDiagnosticLogRecord(logObj: TsLogRecord) {
const meta = logObj._meta as
| {
logLevelName?: string;
@@ -335,7 +319,7 @@ function buildDiagnosticLogRecord(logObj: LogTransportRecord) {
function attachDiagnosticEventTransport(logger: TsLogger<LogObj>): void {
logger.attachTransport((logObj: LogObj) => {
try {
emitDiagnosticEvent(buildDiagnosticLogRecord(logObj as LogTransportRecord));
emitDiagnosticEvent(buildDiagnosticLogRecord(logObj as TsLogRecord));
} catch {
// never block on logging failures
}
@@ -425,9 +409,6 @@ function buildLogger(settings: ResolvedSettings): TsLogger<LogObj> {
// Silent logging does not write files; skip all filesystem setup in this path.
if (settings.level === "silent") {
attachDiagnosticEventTransport(logger);
for (const transport of externalTransports) {
attachExternalTransport(logger, transport);
}
return logger;
}
@@ -470,9 +451,6 @@ function buildLogger(settings: ResolvedSettings): TsLogger<LogObj> {
}
});
attachDiagnosticEventTransport(logger);
for (const transport of externalTransports) {
attachExternalTransport(logger, transport);
}
return logger;
}
@@ -579,17 +557,6 @@ export function resetLogger() {
loggingState.overrideSettings = null;
}
export function registerLogTransport(transport: LogTransport): () => void {
externalTransports.add(transport);
const logger = loggingState.cachedLogger as TsLogger<LogObj> | null;
if (logger) {
attachExternalTransport(logger, transport);
}
return () => {
externalTransports.delete(transport);
};
}
export const __test__ = {
shouldSkipMutatingLoggingConfigRead,
};

View File

@@ -0,0 +1,25 @@
import {
onInternalDiagnosticEvent,
type DiagnosticEventPayload,
} from "../../infra/diagnostic-events.js";
export type CapturedDiagnosticLogRecord = Extract<DiagnosticEventPayload, { type: "log.record" }>;
export function flushDiagnosticLogRecords(): Promise<void> {
return new Promise<void>((resolve) => setImmediate(resolve));
}
export function createDiagnosticLogRecordCapture() {
const records: CapturedDiagnosticLogRecord[] = [];
const unsubscribe = onInternalDiagnosticEvent((event) => {
if (event.type === "log.record") {
records.push(event);
}
});
return {
records,
flush: flushDiagnosticLogRecords,
cleanup: unsubscribe,
};
}

View File

@@ -1,31 +1,25 @@
import path from "node:path";
import { resolvePreferredOpenClawTmpDir } from "../../infra/tmp-openclaw-dir.js";
import {
registerLogTransport,
resetLogger,
setLoggerOverride,
type LogTransportRecord,
} from "../logger.js";
import { resetLogger, setLoggerOverride } from "../logger.js";
import { createDiagnosticLogRecordCapture } from "./diagnostic-log-capture.js";
export function createWarnLogCapture(prefix: string) {
const records: LogTransportRecord[] = [];
const capture = createDiagnosticLogRecordCapture();
setLoggerOverride({
level: "warn",
consoleLevel: "silent",
file: path.join(resolvePreferredOpenClawTmpDir(), `${prefix}-${process.pid}-${Date.now()}.log`),
});
const unregister = registerLogTransport((record) => {
records.push(record);
});
return {
findText(needle: string): string | undefined {
return records
.flatMap((record) => Object.values(record))
async findText(needle: string): Promise<string | undefined> {
await capture.flush();
return capture.records
.flatMap((record) => [record.message, ...Object.values(record.attributes ?? {})])
.filter((value): value is string => typeof value === "string")
.find((value) => value.includes(needle));
},
cleanup() {
unregister();
capture.cleanup();
setLoggerOverride(null);
resetLogger();
},

View File

@@ -17,7 +17,6 @@ export {
isValidDiagnosticTraceId,
parseDiagnosticTraceparent,
} from "../infra/diagnostic-trace-context.js";
export { registerLogTransport } from "../logging/logger.js";
export { redactSensitiveText } from "../logging/redact.js";
export { emptyPluginConfigSchema } from "../plugins/config-schema.js";
export type {