B1: structured request access log middleware

packages/server/src/index.ts

@@ -9,6 +9,7 @@ import { serve } from "@hono/node-server";
 import { createNodeWebSocket } from "@hono/node-ws";
 import { cors } from "hono/cors";
 import { sentry } from "@hono/sentry";
+import { requestLog } from "./middleware/requestLog.js";
 import piloRoutes from "./routes/pilo.js";
 import { createPiloWsRoute } from "./routes/piloWs.js";
 
@@ -42,6 +43,9 @@ app.use(
   }),
 );
 
+// Structured request access log (metadata only — no path/body/headers/IP).
+app.use("*", requestLog());
+
 // Health check endpoint
 app.get("/health", (c) => {
   return c.json({ status: "ok", timestamp: new Date().toISOString() });

packages/server/src/middleware/requestLog.ts

@@ -0,0 +1,50 @@
+/**
+ * Request log middleware.
+ *
+ * Emits one structured JSON line per HTTP request. Captures only metadata
+ * (method, matched route, status, duration_ms, taskId) — never the full
+ * URL with query string, request body, headers, cookies, or client IP.
+ *
+ * The `taskId` field is populated from the `x-pilo-task-id` response header
+ * (set by route handlers in routes/pilo.ts via the A1 propagation). When the
+ * header is absent — for example WebSocket upgrades, /health, /, or any
+ * future route that doesn't generate a taskId — the field is omitted.
+ *
+ * If you find yourself wanting to log additional context, route the value
+ * through the data-sensitivity check in the plan first: any value derived
+ * from user input or page content must NOT be logged here. The A4 leak
+ * canary will fail in CI if a regression is introduced.
+ */
+import type { Context, Next } from "hono";
+
+interface RequestLogLine {
+  level: "info";
+  msg: "request";
+  method: string;
+  route: string;
+  status: number;
+  duration_ms: number;
+  taskId?: string;
+}
+
+export function requestLog() {
+  return async (c: Context, next: Next): Promise<void> => {
+    const start = Date.now();
+    try {
+      await next();
+    } finally {
+      const durationMs = Date.now() - start;
+      const taskId = c.res?.headers.get("x-pilo-task-id") ?? undefined;
+      const line: RequestLogLine = {
+        level: "info",
+        msg: "request",
+        method: c.req.method,
+        route: c.req.routePath,
+        status: c.res?.status ?? 0,
+        duration_ms: durationMs,
+        ...(taskId ? { taskId } : {}),
+      };
+      console.log(JSON.stringify(line));
+    }
+  };
+}

packages/server/test/middleware/requestLog.test.ts

@@ -0,0 +1,152 @@
+import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
+import { Hono } from "hono";
+import { requestLog } from "../../src/middleware/requestLog.js";
+
+const SENTINEL = "SENSITIVE-CANARY-x9b2";
+
+function captureConsoleLog() {
+  const lines: string[] = [];
+  const original = console.log;
+  console.log = vi.fn((...args: unknown[]) => {
+    lines.push(args.map((a) => (typeof a === "string" ? a : JSON.stringify(a))).join(" "));
+  }) as typeof console.log;
+  return {
+    lines,
+    restore: () => {
+      console.log = original;
+    },
+    parsed: () =>
+      lines
+        .map((l) => {
+          try {
+            return JSON.parse(l) as Record<string, unknown>;
+          } catch {
+            return null;
+          }
+        })
+        .filter((x): x is Record<string, unknown> => x !== null),
+  };
+}
+
+describe("requestLog middleware", () => {
+  let app: Hono;
+  let cap: ReturnType<typeof captureConsoleLog>;
+
+  beforeEach(() => {
+    cap = captureConsoleLog();
+    app = new Hono();
+    app.use("*", requestLog());
+  });
+
+  afterEach(() => {
+    cap.restore();
+  });
+
+  it("logs method, route, status, duration_ms for a basic request", async () => {
+    app.get("/foo", (c) => c.json({ ok: true }));
+    await app.request("/foo");
+
+    const log = cap.parsed()[0];
+    expect(log).toBeDefined();
+    expect(log.method).toBe("GET");
+    expect(log.route).toBe("/foo");
+    expect(log.status).toBe(200);
+    expect(typeof log.duration_ms).toBe("number");
+    expect(log.duration_ms as number).toBeGreaterThanOrEqual(0);
+  });
+
+  it("logs the matched route pattern, not the actual path", async () => {
+    app.get("/users/:id", (c) => c.json({ id: c.req.param("id") }));
+    await app.request("/users/abc123");
+
+    const log = cap.parsed()[0];
+    expect(log.route).toBe("/users/:id");
+  });
+
+  it("never logs the full URL (query strings would leak)", async () => {
+    app.get("/foo", (c) => c.json({ ok: true }));
+    await app.request(`/foo?secret=${SENTINEL}`);
+
+    const allLogs = cap.lines.join("\n");
+    expect(allLogs).not.toContain(SENTINEL);
+    expect(allLogs).not.toContain("secret=");
+  });
+
+  it("never logs the request body", async () => {
+    app.post("/foo", async (c) => {
+      await c.req.json().catch(() => undefined);
+      return c.json({ ok: true });
+    });
+    await app.request("/foo", {
+      method: "POST",
+      headers: { "Content-Type": "application/json" },
+      body: JSON.stringify({ task: SENTINEL }),
+    });
+
+    expect(cap.lines.join("\n")).not.toContain(SENTINEL);
+  });
+
+  it("never logs request headers (auth tokens would leak)", async () => {
+    app.get("/foo", (c) => c.json({ ok: true }));
+    await app.request("/foo", {
+      headers: {
+        Authorization: `Bearer ${SENTINEL}`,
+        Cookie: `session=${SENTINEL}`,
+      },
+    });
+
+    expect(cap.lines.join("\n")).not.toContain(SENTINEL);
+  });
+
+  it("includes taskId when x-pilo-task-id response header is set", async () => {
+    app.get("/foo", (c) => {
+      c.header("x-pilo-task-id", "task-abc-123");
+      return c.json({ ok: true });
+    });
+    await app.request("/foo");
+
+    const log = cap.parsed()[0];
+    expect(log.taskId).toBe("task-abc-123");
+  });
+
+  it("omits taskId when no x-pilo-task-id header is set", async () => {
+    app.get("/foo", (c) => c.json({ ok: true }));
+    await app.request("/foo");
+
+    const log = cap.parsed()[0];
+    expect(log.taskId).toBeUndefined();
+  });
+
+  it("captures 4xx status correctly", async () => {
+    app.get("/foo", (c) => c.json({ error: "not found" }, 404));
+    await app.request("/foo");
+
+    const log = cap.parsed()[0];
+    expect(log.status).toBe(404);
+  });
+
+  it("captures 5xx status correctly", async () => {
+    app.get("/foo", (c) => c.json({ error: "boom" }, 500));
+    await app.request("/foo");
+
+    const log = cap.parsed()[0];
+    expect(log.status).toBe(500);
+  });
+
+  it("logs once per request even with nested routes", async () => {
+    const subApp = new Hono();
+    subApp.get("/bar", (c) => c.json({ ok: true }));
+    app.route("/api", subApp);
+    await app.request("/api/bar");
+
+    expect(cap.parsed()).toHaveLength(1);
+  });
+
+  it("emits a single JSON line per request (parseable)", async () => {
+    app.get("/foo", (c) => c.json({ ok: true }));
+    await app.request("/foo");
+
+    expect(cap.lines).toHaveLength(1);
+    expect(() => JSON.parse(cap.lines[0])).not.toThrow();
+  });
+});