import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"; import { createLogger } from "../setup.js"; import { StructuredLogExporter } from "../exporter.js"; import { ExportResultCode } from "@opentelemetry/core"; import { SeverityNumber } from "@opentelemetry/api-logs"; import type { ReadableLogRecord } from "@opentelemetry/sdk-logs"; // ─── Helpers ────────────────────────────────────────────────────────────────── /** * Capture all lines written to process.stdout during the callback. * Returns parsed NDJSON objects. */ async function captureStdout(fn: () => void | Promise): Promise[]> { const lines: string[] = []; const spy = vi.spyOn(process.stdout, "write").mockImplementation((chunk: unknown) => { if (typeof chunk === "string") { lines.push(...chunk.split("\n").filter(Boolean)); } return true; }); try { await fn(); } finally { spy.mockRestore(); } return lines.map((line) => JSON.parse(line)); } // ─── createLogger / AppLogger ───────────────────────────────────────────────── describe("createLogger", () => { it("emits a valid NDJSON line for info()", async () => { const logger = createLogger({ service: "test-svc" }); const lines = await captureStdout(() => { logger.info("hello world", { requestId: "abc" }); }); expect(lines).toHaveLength(1); const entry = lines[0]; expect(entry.level).toBe("info"); expect(entry.message).toBe("hello world"); expect(entry.service).toBe("test-svc"); expect(entry.requestId).toBe("abc"); expect(typeof entry.timestamp).toBe("string"); // timestamp must be a valid ISO-8601 date expect(new Date(entry.timestamp as string).toISOString()).toBe(entry.timestamp); }); it("emits correct level text for each severity method", async () => { const logger = createLogger({ service: "test-svc", level: "debug" }); for (const [method, expectedLevel] of [ ["debug", "debug"], ["info", "info"], ["warn", "warn"], ["error", "error"], ["fatal", "fatal"], ] as const) { const lines = await captureStdout(() => { logger[method](`${method} message`); }); expect(lines).toHaveLength(1); expect(lines[0].level).toBe(expectedLevel); expect(lines[0].message).toBe(`${method} message`); } }); it("includes version and environment in output when provided", async () => { const logger = createLogger({ service: "test-svc", version: "1.2.3", environment: "staging", }); const lines = await captureStdout(() => { logger.info("tagged message"); }); expect(lines[0].version).toBe("1.2.3"); expect(lines[0].environment).toBe("staging"); }); it("omits version and environment when not provided", async () => { const logger = createLogger({ service: "test-svc" }); const lines = await captureStdout(() => { logger.info("bare message"); }); expect(Object.keys(lines[0])).not.toContain("version"); expect(Object.keys(lines[0])).not.toContain("environment"); }); it("spreads numeric and boolean attributes into top-level fields", async () => { const logger = createLogger({ service: "test-svc" }); const lines = await captureStdout(() => { logger.info("typed attrs", { count: 42, success: true }); }); expect(lines[0].count).toBe(42); expect(lines[0].success).toBe(true); }); }); // ─── Level filtering ────────────────────────────────────────────────────────── describe("AppLogger level filtering", () => { it("suppresses messages below the configured level", async () => { const logger = createLogger({ service: "test-svc", level: "warn" }); const lines = await captureStdout(() => { logger.debug("suppressed debug"); logger.info("suppressed info"); logger.warn("allowed warn"); logger.error("allowed error"); }); expect(lines).toHaveLength(2); expect(lines[0].level).toBe("warn"); expect(lines[1].level).toBe("error"); }); it("emits all levels when level is debug", async () => { const logger = createLogger({ service: "test-svc", level: "debug" }); const lines = await captureStdout(() => { logger.debug("d"); logger.info("i"); logger.warn("w"); logger.error("e"); logger.fatal("f"); }); expect(lines).toHaveLength(5); }); it("only emits fatal when level is fatal", async () => { const logger = createLogger({ service: "test-svc", level: "fatal" }); const lines = await captureStdout(() => { logger.debug("d"); logger.info("i"); logger.warn("w"); logger.error("e"); logger.fatal("f"); }); expect(lines).toHaveLength(1); expect(lines[0].level).toBe("fatal"); }); }); // ─── child() attribute inheritance ─────────────────────────────────────────── describe("AppLogger child()", () => { it("inherits base attributes from parent", async () => { const logger = createLogger({ service: "test-svc" }); const child = logger.child({ requestId: "req-123", component: "auth" }); const lines = await captureStdout(() => { child.info("child message"); }); expect(lines[0].requestId).toBe("req-123"); expect(lines[0].component).toBe("auth"); expect(lines[0].message).toBe("child message"); }); it("call-site attributes override child base attributes", async () => { const logger = createLogger({ service: "test-svc" }); const child = logger.child({ requestId: "base-id" }); const lines = await captureStdout(() => { child.info("override", { requestId: "override-id" }); }); expect(lines[0].requestId).toBe("override-id"); }); it("parent logger is not affected by child attributes", async () => { const logger = createLogger({ service: "test-svc" }); logger.child({ requestId: "req-123" }); // create child to ensure isolation const lines = await captureStdout(() => { logger.info("parent message"); }); expect(Object.keys(lines[0])).not.toContain("requestId"); }); it("child of child accumulates attributes from both ancestors", async () => { const logger = createLogger({ service: "test-svc" }); const child = logger.child({ layer: "A" }); const grandchild = child.child({ layer: "B", extra: "yes" }); const lines = await captureStdout(() => { grandchild.info("deep"); }); // layer from grandchild overrides layer from child expect(lines[0].layer).toBe("B"); expect(lines[0].extra).toBe("yes"); }); }); // ─── StructuredLogExporter ──────────────────────────────────────────────────── describe("StructuredLogExporter", () => { it("calls resultCallback with SUCCESS on normal export", () => { const exporter = new StructuredLogExporter(); const writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true); const callback = vi.fn(); exporter.export([], callback); expect(callback).toHaveBeenCalledWith({ code: ExportResultCode.SUCCESS }); writeSpy.mockRestore(); }); it("calls resultCallback with FAILED when stdout.write throws", () => { const exporter = new StructuredLogExporter(); const writeSpy = vi.spyOn(process.stdout, "write").mockImplementation(() => { throw new Error("EPIPE"); }); const record = { hrTime: [1700000000, 0] as [number, number], severityNumber: SeverityNumber.INFO, body: "test", resource: { attributes: {} }, attributes: {}, } as unknown as ReadableLogRecord; const callback = vi.fn(); exporter.export([record], callback); expect(callback).toHaveBeenCalledWith({ code: ExportResultCode.FAILED }); writeSpy.mockRestore(); }); it("calls resultCallback with FAILED when JSON.stringify throws (circular ref)", () => { const exporter = new StructuredLogExporter(); const writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true); // Create a log record whose attributes contain a circular reference const circular: Record = {}; circular.self = circular; const record = { hrTime: [1700000000, 0] as [number, number], severityNumber: SeverityNumber.INFO, body: "circular test", resource: { attributes: {} }, attributes: circular, } as unknown as ReadableLogRecord; const callback = vi.fn(); exporter.export([record], callback); expect(callback).toHaveBeenCalledWith({ code: ExportResultCode.FAILED }); writeSpy.mockRestore(); }); describe("hrTimeToISO arithmetic", () => { it("converts [seconds, nanoseconds] to correct ISO string", () => { const exporter = new StructuredLogExporter(); const writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true); const lines: Record[] = []; writeSpy.mockImplementation((chunk) => { if (typeof chunk === "string") { lines.push(...chunk.split("\n").filter(Boolean).map((l) => JSON.parse(l))); } return true; }); const epochSeconds = 1700000000; const nanoseconds = 500_000_000; // 0.5 seconds const record = { hrTime: [epochSeconds, nanoseconds] as [number, number], severityNumber: SeverityNumber.INFO, body: "time test", resource: { attributes: {} }, attributes: {}, } as unknown as ReadableLogRecord; const callback = vi.fn(); exporter.export([record], callback); const expectedMs = epochSeconds * 1000 + nanoseconds / 1_000_000; expect(lines[0].timestamp).toBe(new Date(expectedMs).toISOString()); writeSpy.mockRestore(); }); }); }); // ─── requestLogger middleware ───────────────────────────────────────────────── describe("requestLogger middleware", () => { // eslint-disable-next-line @typescript-eslint/no-explicit-any let writeSpy: any; beforeEach(() => { writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true); }); afterEach(() => { writeSpy.mockRestore(); }); function captureLines(): Record[] { const lines: Record[] = []; writeSpy.mockImplementation((chunk: unknown) => { if (typeof chunk === "string") { lines.push(...chunk.split("\n").filter(Boolean).map((l) => JSON.parse(l))); } return true; }); return lines; } it("logs 'Request received' at debug and 'Request completed' at info for 2xx", async () => { const { requestLogger } = await import("../middleware.js"); const { Hono } = await import("hono"); const logger = createLogger({ service: "test-svc", level: "debug" }); const lines = captureLines(); const app = new Hono(); app.use("*", requestLogger(logger)); app.get("/ok", (c) => c.json({ ok: true })); await app.request("/ok"); const received = lines.find((l) => l.message === "Request received"); const completed = lines.find((l) => l.message === "Request completed"); expect(received).toBeDefined(); expect(received?.level).toBe("debug"); expect(completed).toBeDefined(); expect(completed?.level).toBe("info"); expect(completed?.status).toBe(200); expect(typeof completed?.duration_ms).toBe("number"); }); it("logs 'Request completed' at warn for 4xx responses", async () => { const { requestLogger } = await import("../middleware.js"); const { Hono } = await import("hono"); const logger = createLogger({ service: "test-svc", level: "debug" }); const lines = captureLines(); const app = new Hono(); app.use("*", requestLogger(logger)); app.get("/bad", (c) => c.json({ error: "bad request" }, 400)); await app.request("/bad"); const completed = lines.find((l) => l.message === "Request completed"); expect(completed?.level).toBe("warn"); expect(completed?.status).toBe(400); }); it("logs 'Request completed' at error for 5xx responses", async () => { const { requestLogger } = await import("../middleware.js"); const { Hono } = await import("hono"); const logger = createLogger({ service: "test-svc", level: "debug" }); const lines = captureLines(); const app = new Hono(); app.use("*", requestLogger(logger)); app.get("/err", (c) => c.json({ error: "server error" }, 500)); await app.request("/err"); const completed = lines.find((l) => l.message === "Request completed"); expect(completed?.level).toBe("error"); expect(completed?.status).toBe(500); }); it("logs 'Request completed' at error level when handler throws (Hono catches internally)", async () => { const { requestLogger } = await import("../middleware.js"); const { Hono } = await import("hono"); const logger = createLogger({ service: "test-svc", level: "debug" }); const lines = captureLines(); const app = new Hono(); app.use("*", requestLogger(logger)); app.get("/throw", () => { throw new Error("handler crashed"); }); // Hono's internal onError catches the throw and returns 500. // The middleware sees next() return normally with c.res.status = 500. const res = await app.request("/throw"); expect(res.status).toBe(500); // Middleware logs "Request completed" at error (status >= 500), not "Request failed" const completed = lines.find((l) => l.message === "Request completed"); expect(completed).toBeDefined(); expect(completed?.level).toBe("error"); expect(completed?.status).toBe(500); }); it("includes method and path in child logger context", async () => { const { requestLogger } = await import("../middleware.js"); const { Hono } = await import("hono"); const logger = createLogger({ service: "test-svc", level: "debug" }); const lines = captureLines(); const app = new Hono(); app.use("*", requestLogger(logger)); app.get("/api/forum", (c) => c.json({ ok: true })); await app.request("/api/forum"); const completed = lines.find((l) => l.message === "Request completed"); expect(completed?.method).toBe("GET"); expect(completed?.path).toBe("/api/forum"); }); });