Merge pull request #431 from trails-cool/fix/planner-request-id-tracing

feat(planner): per-request requestId propagated through logs

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();
+  });
+});

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<RequestContext>();
 
 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" } }
     : {}),

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