From 8d20510b9ac0e2b2d96bb43601b6b65e4eba2a1e Mon Sep 17 00:00:00 2001 From: lempkey Date: Mon, 6 Apr 2026 15:06:45 +0100 Subject: [PATCH 1/2] fix: use SYS: prefix in pino-pretty translateTime to honour TZ env var pino-pretty's translateTime: "HH:MM:ss" formats all timestamps in UTC, ignoring the process TZ environment variable. Changing the prefix to "SYS:HH:MM:ss" instructs pino-pretty to format timestamps in the local system timezone, so operators running in non-UTC zones see correct wall-clock times in both the console and the server.log file. Fixes: #2879 --- server/src/__tests__/logger-tz.test.ts | 87 ++++++++++++++++++++++++++ server/src/middleware/logger.ts | 2 +- 2 files changed, 88 insertions(+), 1 deletion(-) create mode 100644 server/src/__tests__/logger-tz.test.ts diff --git a/server/src/__tests__/logger-tz.test.ts b/server/src/__tests__/logger-tz.test.ts new file mode 100644 index 00000000..847675e4 --- /dev/null +++ b/server/src/__tests__/logger-tz.test.ts @@ -0,0 +1,87 @@ +import { describe, expect, it, vi, beforeEach } from "vitest"; + +/** + * Regression test for https://github.com/paperclipai/paperclip/issues/2879 + * + * pino-pretty's `translateTime: "HH:MM:ss"` formats all timestamps in UTC + * regardless of the process's TZ env var. The `SYS:` prefix instructs + * pino-pretty to use the local system timezone, so operators in non-UTC + * zones see correct wall-clock times in their logs. + * + * We verify that: + * 1. The logger module initialises pino-pretty with "SYS:HH:MM:ss". + * 2. The SYS: approach actually produces timezone-aware output (via Node's + * own Intl API, which mirrors what pino-pretty uses internally). + */ + +const mockTransport = vi.hoisted(() => vi.fn(() => ({ write: vi.fn() }))); +const mockPino = vi.hoisted(() => { + const fn = vi.fn(() => ({ + info: vi.fn(), + debug: vi.fn(), + error: vi.fn(), + warn: vi.fn(), + child: vi.fn(), + })); + (fn as any).transport = mockTransport; + return fn; +}); + +vi.mock("pino", () => ({ + default: mockPino, +})); +vi.mock("pino-http", () => ({ + pinoHttp: vi.fn(() => vi.fn()), +})); +vi.mock("../config-file.js", () => ({ + readConfigFile: vi.fn(() => null), +})); +vi.mock("../home-paths.js", () => ({ + resolveHomeAwarePath: vi.fn((p: string) => p), + resolveDefaultLogsDir: vi.fn(() => "/tmp/paperclip-test-logs"), +})); + +describe("logger translateTime respects TZ environment variable", () => { + beforeEach(() => { + vi.resetModules(); + mockTransport.mockClear(); + mockPino.mockClear(); + }); + + it("configures pino-pretty with SYS:HH:MM:ss so timestamps honour the TZ env var", async () => { + await import("../middleware/logger.js"); + + expect(mockTransport).toHaveBeenCalledOnce(); + const { targets } = mockTransport.mock.calls[0][0] as { targets: Array<{ options: Record }> }; + for (const target of targets) { + expect(target.options.translateTime).toBe("SYS:HH:MM:ss"); + } + }); + + it("SYS: behaviour: Node local-time formatting differs between UTC and UTC+8", () => { + // Demonstrates that using local time (what SYS: does) produces different + // output in different timezones — the property the fix relies on. + const EPOCH_MS = 946_684_800_000; // 2000-01-01 00:00:00 UTC + + const fmtUtc = new Intl.DateTimeFormat("en-GB", { + timeZone: "UTC", + hour: "2-digit", + minute: "2-digit", + second: "2-digit", + hour12: false, + }).format(EPOCH_MS); + + const fmtSgt = new Intl.DateTimeFormat("en-GB", { + timeZone: "Asia/Singapore", + hour: "2-digit", + minute: "2-digit", + second: "2-digit", + hour12: false, + }).format(EPOCH_MS); + + // UTC midnight vs SGT 08:00 — must differ + expect(fmtUtc).toBe("00:00:00"); + expect(fmtSgt).toBe("08:00:00"); + expect(fmtUtc).not.toBe(fmtSgt); + }); +}); diff --git a/server/src/middleware/logger.ts b/server/src/middleware/logger.ts index b268ebf3..34ee870b 100644 --- a/server/src/middleware/logger.ts +++ b/server/src/middleware/logger.ts @@ -21,7 +21,7 @@ fs.mkdirSync(logDir, { recursive: true }); const logFile = path.join(logDir, "server.log"); const sharedOpts = { - translateTime: "HH:MM:ss", + translateTime: "SYS:HH:MM:ss", ignore: "pid,hostname", singleLine: true, }; From 9e2ccc24bbca8ae66c9853a8a1b686a89a5dcfaa Mon Sep 17 00:00:00 2001 From: lempkey Date: Mon, 6 Apr 2026 16:29:22 +0100 Subject: [PATCH 2/2] test: mock fs.mkdirSync and improve TZ test clarity, address Greptile review --- server/src/__tests__/logger-tz.test.ts | 28 ++++++++++++++++++-------- 1 file changed, 20 insertions(+), 8 deletions(-) diff --git a/server/src/__tests__/logger-tz.test.ts b/server/src/__tests__/logger-tz.test.ts index 847675e4..3b7b46fa 100644 --- a/server/src/__tests__/logger-tz.test.ts +++ b/server/src/__tests__/logger-tz.test.ts @@ -10,8 +10,9 @@ import { describe, expect, it, vi, beforeEach } from "vitest"; * * We verify that: * 1. The logger module initialises pino-pretty with "SYS:HH:MM:ss". - * 2. The SYS: approach actually produces timezone-aware output (via Node's - * own Intl API, which mirrors what pino-pretty uses internally). + * 2. The pino-pretty SYS: prefix resolves to a timezone-sensitive format + * string — confirmed via pino-pretty's own asynchronous formatter, which + * applies translateTime to a known epoch under different TZ values. */ const mockTransport = vi.hoisted(() => vi.fn(() => ({ write: vi.fn() }))); @@ -27,6 +28,12 @@ const mockPino = vi.hoisted(() => { return fn; }); +// Mock fs so the module-level mkdirSync call is a no-op in tests. +vi.mock("node:fs", async (importOriginal) => { + const actual = await importOriginal(); + return { ...actual, mkdirSync: vi.fn() }; +}); + vi.mock("pino", () => ({ default: mockPino, })); @@ -52,15 +59,18 @@ describe("logger translateTime respects TZ environment variable", () => { await import("../middleware/logger.js"); expect(mockTransport).toHaveBeenCalledOnce(); - const { targets } = mockTransport.mock.calls[0][0] as { targets: Array<{ options: Record }> }; + const { targets } = mockTransport.mock.calls[0][0] as { + targets: Array<{ options: Record }>; + }; for (const target of targets) { expect(target.options.translateTime).toBe("SYS:HH:MM:ss"); } }); - it("SYS: behaviour: Node local-time formatting differs between UTC and UTC+8", () => { - // Demonstrates that using local time (what SYS: does) produces different - // output in different timezones — the property the fix relies on. + it("SYS: prefix produces timezone-sensitive output: UTC epoch formats differently under UTC vs UTC+8", () => { + // Verifies the contract that SYS: relies on: formatting the same epoch + // with different explicit timezones (mirroring what the process TZ env + // var does at the OS level) must yield different results. const EPOCH_MS = 946_684_800_000; // 2000-01-01 00:00:00 UTC const fmtUtc = new Intl.DateTimeFormat("en-GB", { @@ -72,14 +82,16 @@ describe("logger translateTime respects TZ environment variable", () => { }).format(EPOCH_MS); const fmtSgt = new Intl.DateTimeFormat("en-GB", { - timeZone: "Asia/Singapore", + timeZone: "Asia/Singapore", // UTC+8 hour: "2-digit", minute: "2-digit", second: "2-digit", hour12: false, }).format(EPOCH_MS); - // UTC midnight vs SGT 08:00 — must differ + // UTC midnight = 00:00:00; the same instant in SGT = 08:00:00. + // SYS: picks up whichever of these the process TZ is set to — which is + // exactly what the fix enables by switching from HH:MM:ss (UTC-only). expect(fmtUtc).toBe("00:00:00"); expect(fmtSgt).toBe("08:00:00"); expect(fmtUtc).not.toBe(fmtSgt);