From 336ec203c1776bfbb510e133bd9a74e09228dfbe Mon Sep 17 00:00:00 2001 From: Adrian Komorek Date: Thu, 21 May 2026 16:09:41 +0200 Subject: [PATCH] feat(logger): prepend ISO 8601 timestamps to log output Closes #97. - Every log line now starts with the current ISO 8601 timestamp so long-running sf serve smithy output can be scanned or correlated across services without external time markers. - Opt-out: set LOG_TIMESTAMPS=0 (e.g. when piping to systemd/journald). - Adds 14 unit tests covering timestamp format, opt-out, and all four log levels. - Updates three existing steward-scheduler spy assertions to account for the new leading timestamp argument. Co-Authored-By: Claude Sonnet 4.6 --- .changeset/logger-timestamps.md | 17 ++ .../src/services/steward-scheduler.test.ts | 3 + packages/smithy/src/utils/logger.bun.test.ts | 215 ++++++++++++++++++ packages/smithy/src/utils/logger.ts | 61 +++-- 4 files changed, 275 insertions(+), 21 deletions(-) create mode 100644 .changeset/logger-timestamps.md create mode 100644 packages/smithy/src/utils/logger.bun.test.ts diff --git a/.changeset/logger-timestamps.md b/.changeset/logger-timestamps.md new file mode 100644 index 00000000..9ab3bafb --- /dev/null +++ b/.changeset/logger-timestamps.md @@ -0,0 +1,17 @@ +--- +"@stoneforge/smithy": patch +--- + +feat(logger): prepend ISO 8601 timestamps to log output + +`createLogger` now prefixes every log line with the current ISO 8601 +timestamp so long-running `sf serve smithy` output can be scanned or +correlated across services without external time markers. + +Before: `[dispatch-daemon] Spawned worker el-4w8y` +After: `2026-05-05T08:21:44.123Z [dispatch-daemon] Spawned worker el-4w8y` + +Users piping to log aggregators that add their own timestamps (systemd, +journald, etc.) can opt out by setting `LOG_TIMESTAMPS=0`. + +Closes #97. diff --git a/packages/smithy/src/services/steward-scheduler.test.ts b/packages/smithy/src/services/steward-scheduler.test.ts index 2670acc2..268e4eb0 100644 --- a/packages/smithy/src/services/steward-scheduler.test.ts +++ b/packages/smithy/src/services/steward-scheduler.test.ts @@ -875,6 +875,7 @@ describe('StewardSchedulerImpl - logging', () => { await scheduler.registerSteward('steward-1' as EntityId); expect(warnSpy).toHaveBeenCalledWith( + expect.stringMatching(/^\d{4}-\d{2}-\d{2}T/), '[steward-scheduler]', expect.stringContaining('Failed to compute next run time'), ); @@ -895,6 +896,7 @@ describe('StewardSchedulerImpl - logging', () => { await scheduler.registerAllStewards(); expect(logSpy).toHaveBeenCalledWith( + expect.stringMatching(/^\d{4}-\d{2}-\d{2}T/), '[steward-scheduler]', expect.stringContaining('Registered 1/1 steward(s)'), ); @@ -912,6 +914,7 @@ describe('StewardSchedulerImpl - logging', () => { await scheduler.start(); expect(logSpy).toHaveBeenCalledWith( + expect.stringMatching(/^\d{4}-\d{2}-\d{2}T/), '[steward-scheduler]', expect.stringContaining('Started with'), ); diff --git a/packages/smithy/src/utils/logger.bun.test.ts b/packages/smithy/src/utils/logger.bun.test.ts new file mode 100644 index 00000000..09b776db --- /dev/null +++ b/packages/smithy/src/utils/logger.bun.test.ts @@ -0,0 +1,215 @@ +/** + * Logger Utility Tests + * + * Covers timestamp injection, opt-out via LOG_TIMESTAMPS=0, and the + * existing log-level filtering behaviour. + */ + +import { describe, it, expect, beforeEach, afterEach, mock, spyOn } from 'bun:test'; +import { createLogger, getLogLevel, timestampsEnabled } from './logger.js'; + +// ============================================================================ +// Helpers +// ============================================================================ + +function withEnv(vars: Record, fn: () => void): void { + const saved: Record = {}; + for (const [k, v] of Object.entries(vars)) { + saved[k] = process.env[k]; + if (v === undefined) { + delete process.env[k]; + } else { + process.env[k] = v; + } + } + try { + fn(); + } finally { + for (const [k, v] of Object.entries(saved)) { + if (v === undefined) { + delete process.env[k]; + } else { + process.env[k] = v; + } + } + } +} + +// ============================================================================ +// timestampsEnabled +// ============================================================================ + +describe('timestampsEnabled', () => { + it('returns true when LOG_TIMESTAMPS is unset', () => { + withEnv({ LOG_TIMESTAMPS: undefined }, () => { + expect(timestampsEnabled()).toBe(true); + }); + }); + + it('returns true when LOG_TIMESTAMPS=1', () => { + withEnv({ LOG_TIMESTAMPS: '1' }, () => { + expect(timestampsEnabled()).toBe(true); + }); + }); + + it('returns false when LOG_TIMESTAMPS=0', () => { + withEnv({ LOG_TIMESTAMPS: '0' }, () => { + expect(timestampsEnabled()).toBe(false); + }); + }); +}); + +// ============================================================================ +// createLogger — timestamp format +// ============================================================================ + +describe('createLogger timestamp', () => { + let logged: unknown[][] = []; + let restore: (() => void) | null = null; + + beforeEach(() => { + logged = []; + const orig = console.log.bind(console); + restore = () => { console.log = orig; }; + console.log = (...args: unknown[]) => { logged.push(args); }; + }); + + afterEach(() => { + restore?.(); + delete process.env.LOG_TIMESTAMPS; + delete process.env.LOG_LEVEL; + }); + + it('prepends an ISO 8601 timestamp when LOG_TIMESTAMPS is unset', () => { + withEnv({ LOG_TIMESTAMPS: undefined }, () => { + const logger = createLogger('test-svc'); + logger.info('hello'); + expect(logged.length).toBe(1); + const ts = logged[0]![0] as string; + // ISO 8601: "2026-05-21T..." + expect(ts).toMatch(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/); + expect(logged[0]![1]).toBe('[test-svc]'); + expect(logged[0]![2]).toBe('hello'); + }); + }); + + it('prepends timestamp when LOG_TIMESTAMPS=1', () => { + withEnv({ LOG_TIMESTAMPS: '1' }, () => { + const logger = createLogger('svc'); + logger.info('msg'); + const ts = logged[0]![0] as string; + expect(ts).toMatch(/^\d{4}-\d{2}-\d{2}T/); + }); + }); + + it('omits timestamp when LOG_TIMESTAMPS=0', () => { + withEnv({ LOG_TIMESTAMPS: '0' }, () => { + const logger = createLogger('svc'); + logger.info('msg'); + expect(logged.length).toBe(1); + // First arg should be the prefix, not a timestamp + expect(logged[0]![0]).toBe('[svc]'); + expect(logged[0]![1]).toBe('msg'); + }); + }); + + it('passes extra args through when timestamps are on', () => { + withEnv({ LOG_TIMESTAMPS: undefined }, () => { + const logger = createLogger('svc'); + const obj = { x: 1 }; + logger.info('msg', obj); + // args: [timestamp, '[svc]', 'msg', obj] + expect(logged[0]!.length).toBe(4); + expect(logged[0]![3]).toBe(obj); + }); + }); + + it('passes extra args through when timestamps are off', () => { + withEnv({ LOG_TIMESTAMPS: '0' }, () => { + const logger = createLogger('svc'); + const obj = { x: 1 }; + logger.info('msg', obj); + // args: ['[svc]', 'msg', obj] + expect(logged[0]!.length).toBe(3); + expect(logged[0]![2]).toBe(obj); + }); + }); +}); + +// ============================================================================ +// createLogger — warn / error / debug also receive timestamps +// ============================================================================ + +describe('createLogger timestamp — all levels', () => { + afterEach(() => { + delete process.env.LOG_TIMESTAMPS; + delete process.env.LOG_LEVEL; + }); + + it('warn includes timestamp', () => { + const warnLog: unknown[][] = []; + const origWarn = console.warn; + console.warn = (...args: unknown[]) => { warnLog.push(args); }; + withEnv({ LOG_TIMESTAMPS: undefined }, () => { + const logger = createLogger('svc'); + logger.warn('oops'); + expect(warnLog.length).toBe(1); + expect((warnLog[0]![0] as string)).toMatch(/^\d{4}-\d{2}-\d{2}T/); + }); + console.warn = origWarn; + }); + + it('error includes timestamp', () => { + const errLog: unknown[][] = []; + const origErr = console.error; + console.error = (...args: unknown[]) => { errLog.push(args); }; + withEnv({ LOG_TIMESTAMPS: undefined }, () => { + const logger = createLogger('svc'); + logger.error('fail'); + expect(errLog.length).toBe(1); + expect((errLog[0]![0] as string)).toMatch(/^\d{4}-\d{2}-\d{2}T/); + }); + console.error = origErr; + }); + + it('debug includes timestamp when LOG_LEVEL=DEBUG', () => { + const dbgLog: unknown[][] = []; + const origDbg = console.debug; + console.debug = (...args: unknown[]) => { dbgLog.push(args); }; + withEnv({ LOG_TIMESTAMPS: undefined, LOG_LEVEL: 'DEBUG' }, () => { + const logger = createLogger('svc'); + logger.debug('verbose'); + expect(dbgLog.length).toBe(1); + expect((dbgLog[0]![0] as string)).toMatch(/^\d{4}-\d{2}-\d{2}T/); + }); + console.debug = origDbg; + }); +}); + +// ============================================================================ +// getLogLevel — existing behaviour unchanged +// ============================================================================ + +describe('getLogLevel', () => { + afterEach(() => { + delete process.env.LOG_LEVEL; + }); + + it('defaults to INFO when LOG_LEVEL is unset', () => { + withEnv({ LOG_LEVEL: undefined }, () => { + expect(getLogLevel()).toBe('INFO'); + }); + }); + + it('returns the configured level', () => { + withEnv({ LOG_LEVEL: 'DEBUG' }, () => { + expect(getLogLevel()).toBe('DEBUG'); + }); + }); + + it('falls back to INFO for an invalid value', () => { + withEnv({ LOG_LEVEL: 'VERBOSE' }, () => { + expect(getLogLevel()).toBe('INFO'); + }); + }); +}); diff --git a/packages/smithy/src/utils/logger.ts b/packages/smithy/src/utils/logger.ts index 4682d067..c15297b7 100644 --- a/packages/smithy/src/utils/logger.ts +++ b/packages/smithy/src/utils/logger.ts @@ -15,6 +15,7 @@ * * Environment: * LOG_LEVEL=DEBUG|INFO|WARNING|ERROR (default: INFO) + * LOG_TIMESTAMPS=0 — set to disable ISO 8601 timestamp prefix (default: enabled) * * @module */ @@ -66,6 +67,20 @@ const VALID_LOG_LEVELS = new Set(['DEBUG', 'INFO', 'WARNING', 'ERROR']); */ const DEFAULT_LOG_LEVEL: LogLevel = 'INFO'; +// ============================================================================ +// Timestamp Control +// ============================================================================ + +/** + * Returns whether log lines should include an ISO 8601 timestamp prefix. + * + * Enabled by default. Set LOG_TIMESTAMPS=0 to opt out (e.g. when piping + * to systemd/journald or another log aggregator that adds its own timestamps). + */ +export function timestampsEnabled(): boolean { + return process.env.LOG_TIMESTAMPS !== '0'; +} + // ============================================================================ // Log Level Resolution // ============================================================================ @@ -111,53 +126,57 @@ function shouldLog(messageLevel: LogLevel): boolean { * ```ts * const logger = createLogger('dispatch-daemon'); * logger.info('Started polling'); - * // Output: [dispatch-daemon] Started polling + * // Output: 2026-05-05T08:21:44.123Z [dispatch-daemon] Started polling * * logger.debug('Checking worker availability'); * // Only shown when LOG_LEVEL=DEBUG + * + * // Opt out of timestamps: + * // LOG_TIMESTAMPS=0 sf serve smithy * ``` */ export function createLogger(serviceName: string): Logger { const prefix = `[${serviceName}]`; + function emit(fn: (...a: unknown[]) => void, message: string, args: unknown[]): void { + if (timestampsEnabled()) { + const ts = new Date().toISOString(); + if (args.length > 0) { + fn(ts, prefix, message, ...args); + } else { + fn(ts, prefix, message); + } + } else { + if (args.length > 0) { + fn(prefix, message, ...args); + } else { + fn(prefix, message); + } + } + } + return { debug(message: string, ...args: unknown[]): void { if (shouldLog('DEBUG')) { - if (args.length > 0) { - console.debug(prefix, message, ...args); - } else { - console.debug(prefix, message); - } + emit(console.debug.bind(console), message, args); } }, info(message: string, ...args: unknown[]): void { if (shouldLog('INFO')) { - if (args.length > 0) { - console.log(prefix, message, ...args); - } else { - console.log(prefix, message); - } + emit(console.log.bind(console), message, args); } }, warn(message: string, ...args: unknown[]): void { if (shouldLog('WARNING')) { - if (args.length > 0) { - console.warn(prefix, message, ...args); - } else { - console.warn(prefix, message); - } + emit(console.warn.bind(console), message, args); } }, error(message: string, ...args: unknown[]): void { if (shouldLog('ERROR')) { - if (args.length > 0) { - console.error(prefix, message, ...args); - } else { - console.error(prefix, message); - } + emit(console.error.bind(console), message, args); } }, };