feat(logger): add ISO 8601 timestamps to log output (closes #97)

.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.

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'),
     );

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<string, string | undefined>, fn: () => void): void {
+  const saved: Record<string, string | undefined> = {};
+  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');
+    });
+  });
+});

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<string>(['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);
       }
     },
   };