fix: add timestamped tool context to logs
This commit is contained in:
@@ -8,6 +8,7 @@ import {
|
||||
enableConsoleCapture,
|
||||
resetLogger,
|
||||
routeLogsToStderr,
|
||||
setConsoleTimestampPrefix,
|
||||
setLoggerOverride,
|
||||
} from "../logging.js";
|
||||
import { loggingState } from "./state.js";
|
||||
@@ -34,6 +35,7 @@ beforeEach(() => {
|
||||
};
|
||||
loggingState.consolePatched = false;
|
||||
loggingState.forceConsoleToStderr = false;
|
||||
loggingState.consoleTimestampPrefix = false;
|
||||
loggingState.rawConsole = null;
|
||||
resetLogger();
|
||||
});
|
||||
@@ -47,6 +49,7 @@ afterEach(() => {
|
||||
console.trace = snapshot.trace;
|
||||
loggingState.consolePatched = false;
|
||||
loggingState.forceConsoleToStderr = false;
|
||||
loggingState.consoleTimestampPrefix = false;
|
||||
loggingState.rawConsole = null;
|
||||
resetLogger();
|
||||
setLoggerOverride(null);
|
||||
@@ -72,6 +75,43 @@ describe("enableConsoleCapture", () => {
|
||||
enableConsoleCapture();
|
||||
expect(() => console.log("hello")).not.toThrow();
|
||||
});
|
||||
|
||||
it("prefixes console output with timestamps when enabled", () => {
|
||||
setLoggerOverride({ level: "info", file: tempLogPath() });
|
||||
const now = new Date("2026-01-17T18:01:02.000Z");
|
||||
vi.useFakeTimers();
|
||||
vi.setSystemTime(now);
|
||||
const warn = vi.fn();
|
||||
console.warn = warn;
|
||||
setConsoleTimestampPrefix(true);
|
||||
enableConsoleCapture();
|
||||
console.warn("[EventQueue] Slow listener detected");
|
||||
expect(warn).toHaveBeenCalledTimes(1);
|
||||
const firstArg = String(warn.mock.calls[0]?.[0] ?? "");
|
||||
expect(firstArg.startsWith("2026-01-17T18:01:02.000Z [EventQueue]")).toBe(true);
|
||||
vi.useRealTimers();
|
||||
});
|
||||
|
||||
it("does not double-prefix timestamps", () => {
|
||||
setLoggerOverride({ level: "info", file: tempLogPath() });
|
||||
const warn = vi.fn();
|
||||
console.warn = warn;
|
||||
setConsoleTimestampPrefix(true);
|
||||
enableConsoleCapture();
|
||||
console.warn("12:34:56 [exec] hello");
|
||||
expect(warn).toHaveBeenCalledWith("12:34:56 [exec] hello");
|
||||
});
|
||||
|
||||
it("leaves JSON output unchanged when timestamp prefix is enabled", () => {
|
||||
setLoggerOverride({ level: "info", file: tempLogPath() });
|
||||
const log = vi.fn();
|
||||
console.log = log;
|
||||
setConsoleTimestampPrefix(true);
|
||||
enableConsoleCapture();
|
||||
const payload = JSON.stringify({ ok: true });
|
||||
console.log(payload);
|
||||
expect(log).toHaveBeenCalledWith(payload);
|
||||
});
|
||||
});
|
||||
|
||||
function tempLogPath() {
|
||||
|
||||
@@ -67,6 +67,10 @@ export function setConsoleSubsystemFilter(filters?: string[] | null): void {
|
||||
loggingState.consoleSubsystemFilter = normalized.length > 0 ? normalized : null;
|
||||
}
|
||||
|
||||
export function setConsoleTimestampPrefix(enabled: boolean): void {
|
||||
loggingState.consoleTimestampPrefix = enabled;
|
||||
}
|
||||
|
||||
export function shouldLogSubsystemToConsole(subsystem: string): boolean {
|
||||
const filter = loggingState.consoleSubsystemFilter;
|
||||
if (!filter || filter.length === 0) {
|
||||
@@ -93,6 +97,33 @@ function isEpipeError(err: unknown): boolean {
|
||||
return code === "EPIPE" || code === "EIO";
|
||||
}
|
||||
|
||||
function formatConsoleTimestamp(style: ConsoleStyle): string {
|
||||
const now = new Date().toISOString();
|
||||
if (style === "pretty") return now.slice(11, 19);
|
||||
return now;
|
||||
}
|
||||
|
||||
function hasTimestampPrefix(value: string): boolean {
|
||||
return /^(?:\d{2}:\d{2}:\d{2}|\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?Z?)/.test(
|
||||
value,
|
||||
);
|
||||
}
|
||||
|
||||
function isJsonPayload(value: string): boolean {
|
||||
const trimmed = value.trim();
|
||||
if (!trimmed.startsWith("{") && !trimmed.startsWith("[")) return false;
|
||||
try {
|
||||
JSON.parse(trimmed);
|
||||
return true;
|
||||
} catch {
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
||||
function stripAnsi(value: string): string {
|
||||
return value.replace(/\u001b\[[0-9;]*m/g, "");
|
||||
}
|
||||
|
||||
/**
|
||||
* Route console.* calls through file logging while still emitting to stdout/stderr.
|
||||
* This keeps user-facing output unchanged but guarantees every console call is captured in log files.
|
||||
@@ -123,6 +154,15 @@ export function enableConsoleCapture(): void {
|
||||
(...args: unknown[]) => {
|
||||
const formatted = util.format(...args);
|
||||
if (shouldSuppressConsoleMessage(formatted)) return;
|
||||
const trimmed = stripAnsi(formatted).trimStart();
|
||||
const shouldPrefixTimestamp =
|
||||
loggingState.consoleTimestampPrefix &&
|
||||
trimmed.length > 0 &&
|
||||
!hasTimestampPrefix(trimmed) &&
|
||||
!isJsonPayload(trimmed);
|
||||
const timestamp = shouldPrefixTimestamp
|
||||
? formatConsoleTimestamp(getConsoleSettings().style)
|
||||
: "";
|
||||
try {
|
||||
// Map console levels to file logger
|
||||
if (level === "trace") {
|
||||
@@ -144,14 +184,27 @@ export function enableConsoleCapture(): void {
|
||||
if (loggingState.forceConsoleToStderr) {
|
||||
// in RPC/JSON mode, keep stdout clean
|
||||
try {
|
||||
process.stderr.write(`${formatted}\n`);
|
||||
const line = timestamp ? `${timestamp} ${formatted}` : formatted;
|
||||
process.stderr.write(`${line}\n`);
|
||||
} catch (err) {
|
||||
if (isEpipeError(err)) return;
|
||||
throw err;
|
||||
}
|
||||
} else {
|
||||
try {
|
||||
orig.apply(console, args as []);
|
||||
if (!timestamp) {
|
||||
orig.apply(console, args as []);
|
||||
return;
|
||||
}
|
||||
if (args.length === 0) {
|
||||
orig.call(console, timestamp);
|
||||
return;
|
||||
}
|
||||
if (typeof args[0] === "string") {
|
||||
orig.call(console, `${timestamp} ${args[0]}`, ...args.slice(1));
|
||||
return;
|
||||
}
|
||||
orig.call(console, timestamp, ...args);
|
||||
} catch (err) {
|
||||
if (isEpipeError(err)) return;
|
||||
throw err;
|
||||
|
||||
@@ -5,6 +5,7 @@ export const loggingState = {
|
||||
overrideSettings: null as unknown,
|
||||
consolePatched: false,
|
||||
forceConsoleToStderr: false,
|
||||
consoleTimestampPrefix: false,
|
||||
consoleSubsystemFilter: null as string[] | null,
|
||||
rawConsole: null as {
|
||||
log: typeof console.log;
|
||||
|
||||
Reference in New Issue
Block a user