diff --git a/src/logger.ts b/src/logger.ts index 8d4ad3790..9765afd78 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -26,16 +26,21 @@ type Fields = Record | undefined; +function ts(): string { + return new Date().toISOString(); +} + function fmt(level: string, msg: string, fields: Fields): string { + const prefix = `${ts()} [agentmemory] ${level}`; if (!fields || Object.keys(fields).length === 0) { - return `[agentmemory] ${level} ${msg}`; + return `${prefix} ${msg}`; } try { - return `[agentmemory] ${level} ${msg} ${JSON.stringify(fields)}`; + return `${prefix} ${msg} ${JSON.stringify(fields)}`; } catch { - // Fields contained a circular reference or a BigInt — fall back + // Fields contained a circular reference or a BigInt - fall back // to the plain message so a log line never throws. - return `[agentmemory] ${level} ${msg}`; + return `${prefix} ${msg}`; } } @@ -88,7 +93,7 @@ export function isBootVerbose(): boolean { export function bootLog(msg: string): void { if (bootVerbose) { try { - process.stderr.write(`[agentmemory] ${msg}\n`); + process.stderr.write(`${ts()} [agentmemory] ${msg}\n`); } catch { // stderr unavailable — drop. } @@ -101,7 +106,7 @@ export function bootWarn(msg: string): void { // Warnings always surface; they're rare and the user needs to see // them even when the rest of the boot log is suppressed. try { - process.stderr.write(`[agentmemory] warn ${msg}\n`); + process.stderr.write(`${ts()} [agentmemory] warn ${msg}\n`); } catch {} } diff --git a/test/logger.test.ts b/test/logger.test.ts new file mode 100644 index 000000000..6d1357d6a --- /dev/null +++ b/test/logger.test.ts @@ -0,0 +1,68 @@ +import { describe, it, expect, vi, afterEach } from "vitest"; + +import { logger, bootLog, bootWarn, setBootVerbose } from "../src/logger.js"; + +const ISO_PREFIX = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z \[agentmemory\] /; + +function spyStderr() { + return vi.spyOn(process.stderr, "write").mockImplementation(() => true); +} + +describe("logger timestamps", () => { + afterEach(() => { + vi.restoreAllMocks(); + setBootVerbose(false); + }); + + it("prefixes info lines with an ISO-8601 UTC timestamp", () => { + const spy = spyStderr(); + logger.info("hello world"); + expect(spy).toHaveBeenCalledTimes(1); + const line = spy.mock.calls[0][0] as string; + expect(line).toMatch(ISO_PREFIX); + expect(line).toContain("[agentmemory] info hello world"); + expect(line.endsWith("\n")).toBe(true); + }); + + it("keeps serialized fields after the message", () => { + const spy = spyStderr(); + logger.warn("with fields", { a: 1, b: "two" }); + const line = spy.mock.calls[0][0] as string; + expect(line).toMatch(ISO_PREFIX); + expect(line).toContain('[agentmemory] warn with fields {"a":1,"b":"two"}'); + }); + + it("never throws on non-serializable fields and still timestamps", () => { + const spy = spyStderr(); + const circular: Record = {}; + circular["self"] = circular; + logger.error("boom", circular); + const line = spy.mock.calls[0][0] as string; + expect(line).toMatch(ISO_PREFIX); + expect(line).toContain("[agentmemory] error boom"); + }); + + it("prefixes bootWarn lines with a timestamp", () => { + const spy = spyStderr(); + bootWarn("boot problem"); + const line = spy.mock.calls[0][0] as string; + expect(line).toMatch(ISO_PREFIX); + expect(line).toContain("[agentmemory] warn boot problem"); + }); + + it("prefixes verbose bootLog lines with a timestamp", () => { + setBootVerbose(true); + const spy = spyStderr(); + bootLog("feature enabled"); + const line = spy.mock.calls[0][0] as string; + expect(line).toMatch(ISO_PREFIX); + expect(line).toContain("[agentmemory] feature enabled"); + }); + + it("does not write quiet bootLog lines to stderr", () => { + setBootVerbose(false); + const spy = spyStderr(); + bootLog("buffered line"); + expect(spy).not.toHaveBeenCalled(); + }); +});