Implement server.mjs debug logging

docs/code-reviews/pr-190-round-2-codex.md

@@ -0,0 +1,36 @@
+# Review: PR #190 server debug logging
+
+Date: 2026-06-08
+Reviewed: PR #190 at 8c4c2dee3857cbbe049270e2a6749cd6394afd9c
+Round: 2
+Label applied: `approved-by-codex-agent`
+
+## What Is Correct
+
+- The security blocker is closed. Sensitive header names now live in a lowercase denylist that includes `authorization`, `x-api-key`, `cookie`, `set-cookie`, and `proxy-authorization`, and `redactHeaders()` case-folds every key before deciding whether to emit `[REDACTED]` (`proxy/server.mjs:26`, `proxy/server.mjs:34`, `proxy/server.mjs:37`). Every debug log call that emits headers now routes through that helper (`proxy/server.mjs:122`, `proxy/server.mjs:152`, `proxy/server.mjs:153`, `proxy/server.mjs:337`). The targeted coverage also exercises Authorization, x-api-key, cookie, proxy-authorization, and the non-sensitive control case (`test/proxy-server-debug-log.test.mjs:116`, `test/proxy-server-debug-log.test.mjs:139`, `test/proxy-server-debug-log.test.mjs:159`, `test/proxy-server-debug-log.test.mjs:175`).
+- The ungated stdout/stderr regression is closed. `debugLog()` is now a no-op unless `CACHE_FIX_DEBUG === "1"` (`proxy/server.mjs:42`, `proxy/server.mjs:43`), and the module-import child-process test asserts zero stdout when the flag is unset (`test/proxy-server-debug-log.test.mjs:196`). I also verified `grep -nE 'console\\.(log|error)' proxy/server.mjs` returns no matches on this head.
+- The async rejection containment bug is closed. `createProxyServer()` now wraps dispatch in an async IIFE and explicitly `await`s both async route handlers inside the surrounding `try/catch` (`proxy/server.mjs:333`, `proxy/server.mjs:354`, `proxy/server.mjs:355`, `proxy/server.mjs:358`). The 500 fallback body is now the constant generic sentinel `{ "error": "internal_proxy_error" }`, with no `error.message` echo (`proxy/server.mjs:360`, `proxy/server.mjs:364`). The new structural checks cover both requirements (`test/proxy-server-debug-log.test.mjs:230`, `test/proxy-server-debug-log.test.mjs:254`).
+- The misleading diagnostics called out in round 1 are corrected. The internal-handled path now logs `clientReq.method` / `clientReq.url`, not nonexistent response-object request fields (`proxy/server.mjs:119`, `proxy/server.mjs:120`). The upstream response log still uses `upstreamRes.statusMessage`, which is the right object for that field, and I found no remaining `clientRes.url`, `clientRes.method`, or `bytesWritten` references in `proxy/server.mjs` at this head (`proxy/server.mjs:150`, `proxy/server.mjs:151`).
+- Verification is strong enough for approval. `node --test test/proxy-server-debug-log.test.mjs` passed `8/8`, and `npm test` passed `1029/1029` locally on `8c4c2dee3857cbbe049270e2a6749cd6394afd9c`.
+
+## Blockers
+
+None.
+
+## What Needs Attention
+
+None.
+
+## Bloat / Non-Functional
+
+None.
+
+## Recommendations
+
+- Optional only: if you want a simpler white-box probe for the redaction helper later, export a small test seam for `redactHeaders()`. The current integration and structural coverage is sufficient for this PR without it.
+
+## Bottom Line
+
+The five round-1 blockers are closed on the maintainer-edited head. Secrets are redacted before any header dump reaches disk, the new debug surface is back behind the opt-in gate, the dispatcher now actually catches awaited async-handler failures, the misleading request/response diagnostics are fixed, and the 500 fallback is generic. With the new targeted coverage and a clean `1029/1029` full-suite run, this is ready for approval.
+
+— Codex review

proxy/server.mjs

@@ -6,6 +6,47 @@ import { streamResponse, createTelemetryRecord } from "./stream.mjs";
 import { loadExtensions, snapshotRegistry, runOnRequest, runOnResponseStart, runOnResponse, getFailedExtensions } from "./pipeline.mjs";
 import { startWatcher } from "./watcher.mjs";
 
+// Debug logging — writes to ~/.claude/cache-fix-debug.log (override path with
+// CACHE_FIX_DEBUG_LOG). Self-gated on CACHE_FIX_DEBUG=1; a no-op otherwise.
+// Env is read on every call so tests (and operators flipping the flag at
+// runtime) see live behavior — same pattern as image-strip's #98 gate.
+import { appendFileSync, mkdirSync } from "node:fs";
+import { homedir } from "node:os";
+import { dirname, join } from "node:path";
+import util from "node:util";
+
+function debugLogPath() {
+  return process.env.CACHE_FIX_DEBUG_LOG ||
+    join(homedir(), ".claude", "cache-fix-debug.log");
+}
+
+// Never spread raw headers to the log: Authorization / x-api-key / cookies
+// must never persist to disk. Same discipline as bootstrap-defense.mjs's
+// audit-record contract — extract named scalars only.
+const SENSITIVE_HEADERS = new Set([
+  "authorization",
+  "x-api-key",
+  "cookie",
+  "set-cookie",
+  "proxy-authorization",
+]);
+
+function redactHeaders(headers) {
+  const out = {};
+  for (const [k, v] of Object.entries(headers || {})) {
+    out[k] = SENSITIVE_HEADERS.has(k.toLowerCase()) ? "[REDACTED]" : v;
+  }
+  return out;
+}
+
+function debugLog(...args) {
+  if (process.env.CACHE_FIX_DEBUG !== "1") return;
+  const path = debugLogPath();
+  try { mkdirSync(dirname(path), { recursive: true }); } catch {}
+  const line = `[${new Date().toISOString()}] ${util.format(...args)}\n`;
+  try { appendFileSync(path, line); } catch {}
+}
+
 function collectBody(req) {
   return new Promise((resolve, reject) => {
     const chunks = [];
@@ -74,7 +115,13 @@ async function handleMessages(clientReq, clientRes) {
   });
 
   const pre = await preForward(clientReq, clientRes, abortController, extSnapshot, "messages");
-  if (pre.handled) return;
+  if (pre.handled) {
+    debugLog("[PROXY] handled internally without upstream request",
+             "method:", clientReq.method, "url:", clientReq.url,
+             "status:", clientRes.statusCode,
+             "response headers:", redactHeaders(clientRes.getHeaders()));
+    return;
+  }
   const { parsed, forwardBody, meta } = pre;
 
   const requestedModel = parsed?.model || null;
@@ -88,6 +135,7 @@ async function handleMessages(clientReq, clientRes) {
       abortController.signal
     ));
   } catch (err) {
+    debugLog("[PROXY] forwardRequest error:", err.message);
     if (abortController.signal.aborted) return;
     clientRes.writeHead(502, { "content-type": "application/json" });
     clientRes.end(JSON.stringify({ error: "upstream_error", message: err.message }));
@@ -99,6 +147,11 @@ async function handleMessages(clientReq, clientRes) {
   // socket carried the request without each one re-instrumenting upstream.
   meta._upstreamConnectionId = upstreamConnectionId ?? null;
 
+  debugLog("[UPSTREAM -> PROXY -> CLAUDE] RESPONSE",
+           "status:", statusCode, "message:", upstreamRes.statusMessage,
+           "upstream headers:", redactHeaders(upstreamRes.headers),
+           "proxy headers:", redactHeaders(responseHeaders));
+
   if (extSnapshot.length > 0) {
     const resCtx = { status: statusCode, headers: responseHeaders, meta };
     await runOnResponseStart(resCtx, extSnapshot);
@@ -274,16 +327,44 @@ function handleNotFound(_req, res) {
  */
 export function createProxyServer() {
   return http.createServer((req, res) => {
-    if (req.method === "GET" && req.url === "/health") {
-      return handleHealth(req, res);
-    }
-    if (req.method === "POST" && req.url?.startsWith("/v1/messages")) {
-      return handleMessages(req, res);
-    }
-    if (req.url?.startsWith("/api/claude_cli/bootstrap")) {
-      return handleBootstrap(req, res);
-    }
-    handleNotFound(req, res);
+    // Async IIFE: handleMessages/handleBootstrap return promises, so we have
+    // to await them inside the try/catch — a bare return would let rejections
+    // escape to unhandledRejection and (on Node 15+) crash the process.
+    (async () => {
+      try {
+        debugLog("[CLAUDE -> PROXY] REQUEST",
+                 "method:", req.method, "url:", req.url,
+                 "headers:", redactHeaders(req.headers));
+
+        // Wrap res.write/res.end to log chunk-level activity when debug is on.
+        // These are sync monkey-patches; the inner debugLog self-gates so the
+        // overhead is negligible when CACHE_FIX_DEBUG is unset.
+        const originalWrite = res.write;
+        const originalEnd = res.end;
+        res.write = function (chunk, ...args) {
+          debugLog(`[PROXY -> CLAUDE] Send chunk. Size: ${chunk ? chunk.length : 0} bytes`);
+          return originalWrite.apply(res, [chunk, ...args]);
+        };
+        res.end = function (chunk, ...args) {
+          debugLog("[PROXY -> CLAUDE] Close connection (res.end)");
+          return originalEnd.apply(res, [chunk, ...args]);
+        };
+
+        if (req.method === "GET" && req.url === "/health") return handleHealth(req, res);
+        if (req.method === "POST" && req.url?.startsWith("/v1/messages")) return await handleMessages(req, res);
+        if (req.url?.startsWith("/api/claude_cli/bootstrap")) return await handleBootstrap(req, res);
+        debugLog("ERROR: handler not found for req.url=", req.url, "method=", req.method);
+        handleNotFound(req, res);
+      } catch (error) {
+        debugLog("REQUEST HANDLER ERROR:", error?.message, error?.stack);
+        // Generic body: do NOT echo error.message (may include internal paths,
+        // upstream URLs, or other server state).
+        if (!res.headersSent) {
+          res.writeHead(500, { "content-type": "application/json" });
+          res.end(JSON.stringify({ error: "internal_proxy_error" }));
+        }
+      }
+    })();
   });
 }