diff --git a/apps/planner/app/lib/logger.server.test.ts b/apps/planner/app/lib/logger.server.test.ts new file mode 100644 index 0000000..e4a5ecb --- /dev/null +++ b/apps/planner/app/lib/logger.server.test.ts @@ -0,0 +1,47 @@ +import { describe, it, expect } from "vitest"; +import { Writable } from "node:stream"; +import pino from "pino"; +import { AsyncLocalStorage } from "node:async_hooks"; + +// Mirrors the journal's logger test — the mixin contract is what +// matters: pino's `mixin` callback reads from AsyncLocalStorage and +// tags every record with the active requestId. + +describe("planner logger mixin attaches requestId from async context", () => { + function captureLogger(als: AsyncLocalStorage<{ requestId: string }>) { + const lines: string[] = []; + const sink = new Writable({ + write(chunk, _enc, cb) { + lines.push(chunk.toString()); + cb(); + }, + }); + const lg = pino( + { + level: "info", + mixin: () => { + const ctx = als.getStore(); + return ctx ? { requestId: ctx.requestId } : {}; + }, + }, + sink, + ); + return { lg, lines }; + } + + it("tags log records with requestId when inside als.run()", () => { + const als = new AsyncLocalStorage<{ requestId: string }>(); + const { lg, lines } = captureLogger(als); + als.run({ requestId: "p-abc" }, () => lg.info("hello")); + const record = JSON.parse(lines[0]!); + expect(record.requestId).toBe("p-abc"); + }); + + it("omits requestId when no async context is active", () => { + const als = new AsyncLocalStorage<{ requestId: string }>(); + const { lg, lines } = captureLogger(als); + lg.info("bare"); + const record = JSON.parse(lines[0]!); + expect(record.requestId).toBeUndefined(); + }); +}); diff --git a/apps/planner/app/lib/logger.server.ts b/apps/planner/app/lib/logger.server.ts index a0454ef..8d1762e 100644 --- a/apps/planner/app/lib/logger.server.ts +++ b/apps/planner/app/lib/logger.server.ts @@ -1,7 +1,25 @@ import pino from "pino"; +import { AsyncLocalStorage } from "node:async_hooks"; + +/** + * Per-request context propagated through the async stack. The HTTP + * server wraps each request in `requestContext.run({ requestId }, ...)` + * so every downstream `logger.info(...)` automatically tags log lines + * with `requestId` — see apps/journal/app/lib/logger.server.ts for the + * same pattern in the journal app. + */ +export interface RequestContext { + requestId: string; +} + +export const requestContext = new AsyncLocalStorage(); export const logger = pino({ level: process.env.LOG_LEVEL ?? "info", + mixin: () => { + const ctx = requestContext.getStore(); + return ctx ? { requestId: ctx.requestId } : {}; + }, ...(process.env.NODE_ENV !== "production" ? { transport: { target: "pino-pretty" } } : {}), diff --git a/apps/planner/server.ts b/apps/planner/server.ts index c480bce..03f8147 100644 --- a/apps/planner/server.ts +++ b/apps/planner/server.ts @@ -1,6 +1,7 @@ import * as Sentry from "@sentry/node"; import { nodeSentryConfig, drop404s } from "@trails-cool/sentry-config"; -import { logger } from "./app/lib/logger.server.ts"; +import { logger, requestContext } from "./app/lib/logger.server.ts"; +import { randomUUID } from "node:crypto"; import { httpRequestDuration } from "./app/lib/metrics.server.ts"; import { createRequestListener } from "@react-router/node"; import { createServer, type IncomingMessage, type ServerResponse } from "node:http"; @@ -92,23 +93,32 @@ const server = createServer((req, res) => { const url = req.url ?? "/"; const start = Date.now(); - // Log and track request on finish (skip static assets and health/metrics) - if (!url.startsWith("/assets/") && url !== "/health" && url !== "/metrics") { - res.on("finish", () => { - const duration = Date.now() - start; - logger.info({ method: req.method, path: url, status: res.statusCode, duration }, "request"); - httpRequestDuration.observe( - { method: req.method ?? "GET", route: url.split("?")[0]!, status: String(res.statusCode) }, - duration / 1000, - ); - }); - } + // Honor an inbound X-Request-Id (e.g. from Caddy or a probe) so the + // request ID propagates across the proxy hop; otherwise mint a fresh + // UUID. Echo on the response so clients can correlate. + const inbound = req.headers["x-request-id"]; + const requestId = + (Array.isArray(inbound) ? inbound[0] : inbound) || randomUUID(); + res.setHeader("X-Request-Id", requestId); - if (url === "/health") { handleHealth(req, res); return; } - if (url === "/metrics") { handleMetrics(req, res); return; } - if (!serveStatic(req, res)) { - listener(req, res); - } + requestContext.run({ requestId }, () => { + if (!url.startsWith("/assets/") && url !== "/health" && url !== "/metrics") { + res.on("finish", () => { + const duration = Date.now() - start; + logger.info({ method: req.method, path: url, status: res.statusCode, duration }, "request"); + httpRequestDuration.observe( + { method: req.method ?? "GET", route: url.split("?")[0]!, status: String(res.statusCode) }, + duration / 1000, + ); + }); + } + + if (url === "/health") { handleHealth(req, res); return; } + if (url === "/metrics") { handleMetrics(req, res); return; } + if (!serveStatic(req, res)) { + listener(req, res); + } + }); }); setupYjsWebSocket(server);