Implement structured logging with pino (P2.17)

Add pino-based logger module for production observability:
- JSON output to stdout for log aggregators (Loki, ELK)
- Configurable via LOG_LEVEL environment variable (defaults to "info")
- Log levels: error, warn, info, debug
- Error objects serialized with type, message, and stack trace
- Child logger support for bound context
- ISO 8601 timestamps in all log entries

Test coverage: 16 tests covering JSON format, log levels, error
serialization, and child loggers.

Total tests now: 553 passing across 31 test files.

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
This commit is contained in:
2026-01-11 08:29:31 +00:00
parent 2ffee63a59
commit 5ec3aba8b3
5 changed files with 352 additions and 16 deletions

213
src/lib/logger.test.ts Normal file
View File

@@ -0,0 +1,213 @@
// ABOUTME: Tests for the pino-based structured logging module.
// ABOUTME: Validates JSON output format, log levels, and field requirements per observability spec.
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
// We'll need to mock stdout to capture log output
const mockStdoutWrite = vi.fn();
const originalStdoutWrite = process.stdout.write.bind(process.stdout);
describe("logger", () => {
beforeEach(() => {
vi.resetModules();
process.stdout.write = mockStdoutWrite as typeof process.stdout.write;
mockStdoutWrite.mockClear();
});
afterEach(() => {
process.stdout.write = originalStdoutWrite;
delete process.env.LOG_LEVEL;
});
describe("log format", () => {
it("outputs valid JSON", async () => {
const { logger } = await import("./logger");
logger.info("test message");
expect(mockStdoutWrite).toHaveBeenCalled();
const output = mockStdoutWrite.mock.calls[0][0];
expect(() => JSON.parse(output)).not.toThrow();
});
it("includes timestamp in ISO 8601 format", async () => {
const { logger } = await import("./logger");
logger.info("test message");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.timestamp).toBeDefined();
// ISO 8601 format check
expect(new Date(output.timestamp).toISOString()).toBe(output.timestamp);
});
it("includes level as string label", async () => {
const { logger } = await import("./logger");
logger.info("test message");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.level).toBe("info");
});
it("includes message field", async () => {
const { logger } = await import("./logger");
logger.info("test message");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.message).toBe("test message");
});
});
describe("log levels", () => {
it("logs info level messages", async () => {
const { logger } = await import("./logger");
logger.info("info message");
expect(mockStdoutWrite).toHaveBeenCalled();
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.level).toBe("info");
expect(output.message).toBe("info message");
});
it("logs warn level messages", async () => {
const { logger } = await import("./logger");
logger.warn("warn message");
expect(mockStdoutWrite).toHaveBeenCalled();
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.level).toBe("warn");
expect(output.message).toBe("warn message");
});
it("logs error level messages", async () => {
const { logger } = await import("./logger");
logger.error("error message");
expect(mockStdoutWrite).toHaveBeenCalled();
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.level).toBe("error");
expect(output.message).toBe("error message");
});
});
describe("additional fields", () => {
it("includes additional context fields", async () => {
const { logger } = await import("./logger");
logger.info({ userId: "user123", duration_ms: 1250 }, "sync complete");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.userId).toBe("user123");
expect(output.duration_ms).toBe(1250);
expect(output.message).toBe("sync complete");
});
it("includes nested objects in context", async () => {
const { logger } = await import("./logger");
logger.info(
{
userId: "user123",
metrics: { bodyBattery: 95, hrvStatus: "Balanced" },
},
"Garmin sync completed",
);
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.userId).toBe("user123");
expect(output.metrics).toEqual({
bodyBattery: 95,
hrvStatus: "Balanced",
});
});
});
describe("error logging", () => {
it("includes error stack trace for Error objects", async () => {
const { logger } = await import("./logger");
const error = new Error("Something went wrong");
logger.error({ err: error }, "Operation failed");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.err).toBeDefined();
expect(output.err.message).toBe("Something went wrong");
expect(output.err.stack).toBeDefined();
expect(output.err.stack).toContain("Error: Something went wrong");
});
it("includes error type for Error objects", async () => {
const { logger } = await import("./logger");
class CustomError extends Error {
constructor(message: string) {
super(message);
this.name = "CustomError";
}
}
const error = new CustomError("Custom error occurred");
logger.error({ err: error }, "Custom failure");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.err.type).toBe("CustomError");
});
});
describe("log level configuration", () => {
it("defaults to info level when LOG_LEVEL not set", async () => {
delete process.env.LOG_LEVEL;
const { logger } = await import("./logger");
// Debug should not be logged at info level
logger.debug("debug message");
expect(mockStdoutWrite).not.toHaveBeenCalled();
// Info should be logged
logger.info("info message");
expect(mockStdoutWrite).toHaveBeenCalled();
});
it("respects LOG_LEVEL environment variable for debug", async () => {
process.env.LOG_LEVEL = "debug";
const { logger } = await import("./logger");
logger.debug("debug message");
expect(mockStdoutWrite).toHaveBeenCalled();
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.level).toBe("debug");
});
it("respects LOG_LEVEL environment variable for error only", async () => {
process.env.LOG_LEVEL = "error";
const { logger } = await import("./logger");
logger.info("info message");
logger.warn("warn message");
expect(mockStdoutWrite).not.toHaveBeenCalled();
logger.error("error message");
expect(mockStdoutWrite).toHaveBeenCalled();
});
});
describe("child loggers", () => {
it("creates child logger with bound context", async () => {
const { logger } = await import("./logger");
const childLogger = logger.child({ userId: "user123" });
childLogger.info("child message");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.userId).toBe("user123");
expect(output.message).toBe("child message");
});
it("child logger inherits parent context", async () => {
const { logger } = await import("./logger");
const childLogger = logger.child({ service: "garmin-sync" });
const grandchildLogger = childLogger.child({ userId: "user123" });
grandchildLogger.info("nested message");
const output = JSON.parse(mockStdoutWrite.mock.calls[0][0]);
expect(output.service).toBe("garmin-sync");
expect(output.userId).toBe("user123");
});
});
});

26
src/lib/logger.ts Normal file
View File

@@ -0,0 +1,26 @@
// ABOUTME: Structured logging module using pino for JSON output to stdout.
// ABOUTME: Configurable via LOG_LEVEL env var, outputs parseable logs for aggregators.
import pino from "pino";
/**
* PhaseFlow logger configured per observability spec.
*
* Log levels: error, warn, info, debug
* Output: JSON to stdout
* Configuration: LOG_LEVEL env var (defaults to "info")
*
* Usage:
* logger.info({ userId: "123" }, "User logged in");
* logger.error({ err: error, userId: "123" }, "Operation failed");
*/
export const logger = pino({
level: process.env.LOG_LEVEL || "info",
formatters: {
level: (label) => ({ level: label }),
},
timestamp: () => `,"timestamp":"${new Date().toISOString()}"`,
messageKey: "message",
});
export type Logger = typeof logger;