From 27c9cfcf6d392f8a4620a0e55415dc4f55e2ce84 Mon Sep 17 00:00:00 2001 From: Hleb Shauchenka Date: Sat, 20 Jun 2026 19:26:41 +0200 Subject: [PATCH 1/2] chore(observability): prefix log lines with an ISO-8601 UTC timestamp Prefix every log line emitted by logger.fmt, bootLog, and bootWarn with an ISO-8601 UTC timestamp: [agentmemory] . Quiet-mode buffered boot lines stay plain to keep the CLI summary clean. Docker logs and any persisted log file now carry per-line timestamps for downstream tail/grep/log-aggregator work. Tests: test/logger.test.ts (new file) covers info/warn/error, field serialization, non-serializable fallback, bootWarn, and verbose bootLog. Signed-off-by: Hleb Shauchenka --- src/logger.ts | 17 ++++++++----- test/logger.test.ts | 61 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 72 insertions(+), 6 deletions(-) create mode 100644 test/logger.test.ts 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..9bd403e83 --- /dev/null +++ b/test/logger.test.ts @@ -0,0 +1,61 @@ +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"); + }); +}); From df985b5039907c311a103ef5f94b6d85462b4ab7 Mon Sep 17 00:00:00 2001 From: Hleb Shauchenka Date: Sat, 20 Jun 2026 22:32:45 +0200 Subject: [PATCH 2/2] test(logger): cover quiet bootLog buffering path The verbose-mode test asserted the stderr write happens; this adds the counterpart asserting setBootVerbose(false) + bootLog() does NOT touch stderr, locking in the buffered/non-timestamped contract. --- test/logger.test.ts | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/test/logger.test.ts b/test/logger.test.ts index 9bd403e83..6d1357d6a 100644 --- a/test/logger.test.ts +++ b/test/logger.test.ts @@ -58,4 +58,11 @@ describe("logger timestamps", () => { 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(); + }); });