Skip to content

Implement server.mjs debug logging - #190

Merged
cnighswonger merged 3 commits into
cnighswonger:mainfrom
nisqatsi:feature/server-debug-logging
Jun 8, 2026
Merged

Implement server.mjs debug logging#190
cnighswonger merged 3 commits into
cnighswonger:mainfrom
nisqatsi:feature/server-debug-logging

Conversation

@nisqatsi

@nisqatsi nisqatsi commented Jun 4, 2026

Copy link
Copy Markdown
Contributor

No description provided.

@cnighswonger cnighswonger added enhancement New feature or request community-reported Originally reported by a community member P1 High — near-term target labels Jun 4, 2026

@vsits-proxy-builder vsits-proxy-builder Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the contribution! Debug-logging surfaces are useful for the "I can't reproduce this" diagnostic class, and proxy/server.mjs is the right place to add one. Before I can take a formal position on the PR (approve or request-changes), there are several things I'd want to talk through. None of them are dealbreakers — the intent is sound — but they do need to be addressed before merge. Detail below, grouped by class of concern.

Tests pass on your branch, but...

npm test returns 907/907 on your branch. (Note: that's because your branch is based on 3c97e32 from v3.9.0 — main is now at 981/981 after #192 landed today. A rebase will be clean, no file overlap.) The full suite doesn't catch the runtime issues I'm about to flag because:

  1. The new code paths don't have new tests
  2. The unconditional logging fires below the test runner's noise floor

Real concerns

1. Unconditional console.log at module top-level (line 18-26 of new code)

console.log(`config.port='${config.port}'`);
console.log(`config.bind='${config.bind}'`);
// ... 7 more

These fire on every import of proxy/server.mjs — including in tests, in production at boot, anywhere the module is imported. I verified by importing the module in a one-liner: it dumps 9 config values to stdout unconditionally, regardless of CACHE_FIX_DEBUG.

I think the intent was "log config at startup for diagnostic," but as written this is unconditional spam. Two options:

  • Gate behind if (config.debug) like debugLog() already does (probably what you wanted)
  • Move into a dedicated startup log call that fires once per server-start, not once per import

Either way: this is a real concern, not a nit.

2. console.error("[PROXY] forwardRequest error: ...") at line 132 fires regardless of debug mode

} catch (err) {
  console.error("[PROXY] forwardRequest error:", err.message);
  debugLog("[PROXY] forwardRequest error:", err.message);

Same shape as above — the console.error fires whether CACHE_FIX_DEBUG is on or not. The existing debugLog() call is the right channel; the console.error is redundant when debug is on, and noisy stderr in production when debug is off. Drop the console.error, keep the debugLog.

Same applies to the console.error calls in the new try/catch at line 351 ("!!! REQUEST HANDLER ERROR !!!").

3. res.url / res.method / res.statusMessage don't exist on response objects

Several of the new debugLog calls reference properties that don't exist on http.ServerResponse:

debugLog("url:", clientRes.url);          // undefined — res has no .url
debugLog("method:", clientRes.method);    // undefined — res has no .method
debugLog("message:", clientRes.statusMessage);  // undefined on outbound res

I verified empirically — res.url, res.method, res.statusMessage are all undefined on http.ServerResponse. These are req properties (or they exist on IncomingMessage for received responses). The log lines as written will emit url: undefined method: undefined message: undefined.

I think you wanted the corresponding clientReq properties, which are accessible because clientReq is in scope in handleMessages. Same likely applies to the upstreamRes lines lower down — those should probably be referencing clientReq.

4. res.write / res.end monkey-patching is more than logging

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) { ... };

This pattern changes the behavior of every response, not just adds logging. The wrap is harmless in the common case but has a few sharp edges:

  • chunk.length measures bytes for Buffer but characters for strings. The log says "bytes" but isn't always bytes. Use Buffer.byteLength(chunk) if you want consistent byte counts.
  • Wrapping happens unconditionally even when config.debug is false — same issue as #1 above. Every response goes through the wrapper for nothing.
  • This adds a function-call layer to every chunk write — measurable overhead on streaming responses if the proxy is under heavy load.

If you only want this logging when debug is on, gate the wrap behind if (config.debug).

5. The try/catch wrapping the entire request handler is a substantive behavior change

try { ... } catch (error) {
  // Reply error 500 to prevent claude hanging
  if (!res.headersSent) {
    res.writeHead(500, { 'Content-Type': 'application/json' });
    res.end(JSON.stringify({ error: "Internal Proxy Error", message: error.message }));
  }
}

This is actually a good idea on its own — proxies should not let exceptions crash the server. But it's a behavior change well beyond "add debug logging." If you want this, it deserves to be its own PR (or at least called out in this PR's description) so it gets reviewed on its own merits, not bundled into a logging change.

Specifically:

  • error.message is leaked in the response body — for a corp-deployed proxy that's an information disclosure that may not be acceptable
  • The 500 fallback may mask bugs the existing code path would have surfaced (current behavior: uncaught throw → Node crashes → systemd restart → operator notices)

6. PR has no description

The PR body is empty. A community contribution's PR body is the place to say "I needed this to debug X" or "I want to see what's happening when Y." That context shapes the review and helps maintainers prioritize. Even one sentence helps.

Smaller things (would address with the above)

  • import util from 'util' uses default-import + single quotes while the rest of the file uses destructured imports + double quotes. Style nit.
  • appendFileSync / readFileSync / writeFileSync / mkdirSync / renameSync are imported but only appendFileSync is used. Trim unused imports.
  • The new imports sit below startWatcher import rather than at the top of the file with everything else. Conventional style puts all imports in one block.

Disposition

I'm posting this as --comment rather than --request-changes because the intent of the PR is good and the issues are addressable. But the unconditional logging + the res.url/res.method confusion + the monkey-patching defaults are real concerns that need to be addressed before merge.

If you'd like, I can:

  • Walk through specific patches for each numbered item, OR
  • Push corrections to your branch (you have maintainerCanModify enabled), OR
  • Wait for you to iterate

I'll also trigger an independent Codex review next; he often catches things I miss. We'll synthesize both reads and come back to you with a consolidated path forward.

Thanks for picking up something useful — debug logging really is a gap in our diagnostic story. Looking forward to landing this once we work through the details.

— Proxy Builder

@vsits-codex-review-agent vsits-codex-review-agent Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Codex review:

  1. proxy/server.mjs:321-323 writes raw request headers to ~/.claude/cache-fix-debug.log. On this proxy surface that can persist Authorization / x-api-key, and the repo architecture docs say auth headers must never appear in logs. Please redact or drop header dumps before merge.

  2. proxy/server.mjs:29-37, 132, 347, and 352-353 add ungated stdout/stderr output even when CACHE_FIX_DEBUG is off. For an embeddable module, debug surfaces need to stay behind the existing opt-in flag.

  3. proxy/server.mjs:317-359 does not actually catch the async failures it claims to catch. handleMessages() and handleBootstrap() are async, but the request callback returns their promises without await, so rejections bypass this try/catch.

  4. proxy/server.mjs:111-115, 148-153, and 328-335 produce misleading diagnostics: the logged request/response fields are absent or semantically wrong on those objects, and the byte counters are socket-lifetime write counters rather than per-response payload sizes. For a debug PR, incorrect logs are a blocker.

  5. I checked the bootstrap-route question against current main: /api/claude_cli/bootstrap is not duplicated by this PR. The route already exists on main; this patch only re-houses that existing branch inside the new wrapper.

  6. If the 500 fallback stays in a future revision, please keep the client body generic rather than echoing error.message.

Detailed artifact: docs/code-reviews/pr-190-server-debug-logging-codex-review-2026-06-04.md on branch consult/pr-190-codex-review at fba123d.

The intent of the contribution is good. I would welcome a narrowed follow-up that keeps the diagnostics opt-in, redacted, and behavior-preserving.

— Codex review

@vsits-codex-review-agent vsits-codex-review-agent Bot added the changes-requested Blocking review findings are outstanding label Jun 4, 2026
@vsits-proxy-builder

Copy link
Copy Markdown
Contributor

Codex's independent review surfaced two critical concerns I missed plus sharpened a third I'd flagged loosely. Crediting him because these reshape the path forward significantly:

The big one I missed: Authorization headers in the debug log

Codex flagged: debugLog("headers:", req.headers) writes the complete request header set to ~/.claude/cache-fix-debug.log — which for this proxy includes Authorization and x-api-key (the user's Anthropic API key or OAuth token). Cache-fix's architecture explicitly forbids logging auth-bearing headers anywhere. The ~/.claude/ directory is user-readable but the file ends up on backups, in tarballs sent to support, etc. — putting API keys into it is a real security regression we'd be shipping.

Fix shape: redact authorization, x-api-key, and any cookie headers before writing anything header-related to disk. A small helper like:

function redactHeaders(headers) {
  const out = {};
  for (const [k, v] of Object.entries(headers)) {
    const lc = k.toLowerCase();
    out[k] = (lc === "authorization" || lc === "x-api-key" || lc.startsWith("cookie")) ? "[REDACTED]" : v;
  }
  return out;
}

This blocker needs to land before any version of this PR is merged. It's the most important thing on the list.

The try/catch doesn't actually catch what you wanted

I flagged the try/catch as "a substantive behavior change beyond logging" in my original review, but Codex caught something I missed: handleMessages() and handleBootstrap() are async, and the server callback returns their promises without await. So unhandled rejections from those async handlers bypass the try/catch entirely — they propagate as unhandled promise rejections, which is what was happening before this PR.

In other words, the catch as written wraps only the synchronous routing decision (which already couldn't throw), not the actual request-handler bodies. The "prevent claude hanging" intent doesn't work.

If you want this containment, the shape is:

const handler = req.method === "POST" && req.url?.startsWith("/v1/messages")
  ? handleMessages
  : ...;
void handler(req, res).catch((err) => {
  debugLog("[PROXY] handler rejected:", err.message);
  if (!res.headersSent) {
    res.writeHead(500, { 'Content-Type': 'application/json' });
    res.end(JSON.stringify({ error: "Internal Proxy Error" })); // generic — don't leak err.message
  }
});

But as Codex notes, that's a separate change from "add debug logging." It deserves its own PR with its own review.

The bytes/url/method confusions are deeper than my first read

Codex confirmed what I flagged (res.url / res.method are undefined on response objects) and added:

  • upstreamRes.url is the empty-string placeholder, upstreamRes.method is null on client-side IncomingMessage objects — so even the upstream-side logs are misleading
  • bytesWritten is a socket-lifetime counter, not per-response payload size — it accumulates across keepalive connections. The "bytes" number is meaningless for what the author seems to want.

So three of the diagnostic fields don't measure what their labels say. A debug feature whose output misstates the request/response shape sets up future bug reports based on misread logs.

Consolidated path forward

I think the cleanest way to land something useful here is to scope this PR down to just the opt-in debugLog() infrastructure, with all the corrections:

  1. ✅ Keep the debugLog() function gated on config.debug (already correct)
  2. Remove the 9 unconditional top-level console.log config dumps
  3. Remove the unconditional console.error lines
  4. Remove the res.write / res.end monkey-patching (or gate it behind config.debug AND fix the byte-counting AND fix the chunk-as-string vs chunk-as-Buffer handling)
  5. Remove the try/catch wrapper (it doesn't catch what it claims to anyway — leave it for a separate PR if you want true error containment)
  6. Add header redaction for any request-header logging that stays in
  7. Fix the res.url / clientRes.url confusion — use clientReq.url, clientReq.method, clientReq.headers (redacted)
  8. Trim the unused imports (readFileSync, writeFileSync, mkdirSync, renameSync)
  9. Add a one-paragraph PR body explaining the use case

What's left after that is a small, focused, opt-in diagnostic that's safe to ship.

How I can help

Three options, your choice:

  1. You iterate — apply the above changes yourself, push to your branch, we re-review
  2. I push the corrections directly to your branch (you have maintainerCanModify) — you can review the diff before we merge
  3. You and I pair on it — comment here with whichever items you want to discuss and I'll help shape the patch

The intent of the PR is genuinely useful — debug logging IS a gap in cache-fix's diagnostic story. The current implementation just has more rough edges than I can approve. Looking forward to landing this once we work through it.

— Proxy Builder

Aleksandr Usenko and others added 2 commits June 8, 2026 17:26
…c 500 (cnighswonger#190 round 2)

Addresses Codex round-1 review (2026-06-04T21:43Z, CHANGES_REQUESTED):

1. Authorization / x-api-key / cookie / proxy-authorization redacted in
   debug log via a small redactHeaders() helper. Same discipline as
   bootstrap-defense.mjs's audit-record contract: never spread raw headers
   to log code. [REDACTED] sentinel preserves "header was present" signal.

2. Gated all stdout/stderr behind CACHE_FIX_DEBUG. Removed the nine
   module-top console.log(config.X) lines (fired on every import,
   embedder-hostile) and the four ungated console.error() calls in the
   dispatcher / forwardRequest catch. All debug surfaces now flow through
   debugLog, which self-gates on process.env.CACHE_FIX_DEBUG === "1".

3. Dispatcher now awaits handleMessages / handleBootstrap inside an
   async IIFE wrapped by try/catch — rejections from preForward() or
   pipeline hooks no longer escape to unhandledRejection.

4. Fixed two misleading diagnostics: clientRes.url / .method are
   undefined (those are request fields); replaced with clientReq.method /
   .url in the pre.handled branch. Removed the bytesWritten lines (those
   are socket-lifetime counters, not per-response payloads).

5. 500 fallback body is generic ({"error":"internal_proxy_error"}) — no
   longer echoes error.message, which could leak internal paths or
   upstream URLs.

Also:
- Removed unused fs imports (readFileSync/writeFileSync/renameSync).
- Wired mkdirSync for log-dir bootstrap (was imported but unwired).
- LOG_PATH now overridable via CACHE_FIX_DEBUG_LOG for test isolation.
- Live env read on every debugLog call (matches image-strip's cnighswonger#98 gate).

Test coverage in test/proxy-server-debug-log.test.mjs:
- /health hit with debug off creates no log file (no-noise control)
- Authorization / x-api-key / cookie / proxy-authorization all redact
- Non-sensitive header values still appear (over-redaction guard)
- Module import produces no stdout when CACHE_FIX_DEBUG unset (spawn child)
- Static: 500 body has no error.message echo; dispatcher awaits handlers

Co-authored-by: Aleksandr Usenko <nisqatsi@users.noreply.github.com>
@vsits-proxy-builder
vsits-proxy-builder Bot force-pushed the feature/server-debug-logging branch from 2b73759 to 8c4c2de Compare June 8, 2026 17:40
@vsits-proxy-builder

Copy link
Copy Markdown
Contributor

@nisqatsi — Chris cleared us to land this rather than block on iterations, since you've been moving fast on #188 and #189. I pushed 8c4c2de to your branch covering all five Codex round-1 blockers; this preserves the intent (route-level request/response trace gated by CACHE_FIX_DEBUG=1, persistent log at ~/.claude/cache-fix-debug.log) while closing the security and correctness gaps. Author attribution lands as you when this squashes to main.

Headline changes in proxy/server.mjs:

  1. Authorization / x-api-key / cookie / proxy-authorization now redacted before they hit the log. Small redactHeaders(...) helper + SENSITIVE_HEADERS Set. Matches the discipline in proxy/extensions/bootstrap-defense.mjs:68-72 and AGENTS.md §Security (the proxy handles API keys; raw headers must never persist to disk).
  2. All stdout/stderr gated behind CACHE_FIX_DEBUG. Removed the nine module-top console.log(config.X) lines (they fired on every import — bad for embedders) and the four console.error(...) calls in the dispatcher. Everything routes through debugLog(...), which self-gates.
  3. Async rejections actually caught now. Converted the dispatcher into an async IIFE so handleMessages / handleBootstrap are awaited inside the surrounding try/catch. Without this, rejections from preForward() or the extension pipeline escaped to unhandledRejection (crashes the process on Node 15+).
  4. Fixed two undefined-field log lines. clientRes.url / clientRes.method are request fields, not response fields — replaced with clientReq.method / clientReq.url in the pre.handled branch. Dropped clientRes.socket?.bytesWritten (socket-lifetime, not per-response).
  5. 500 fallback body is generic{"error":"internal_proxy_error"} instead of echoing error.message, which could leak internal paths or upstream URLs.

Bonus:

  • Removed the unused readFileSync / writeFileSync / renameSync imports.
  • Wired mkdirSync for log-dir bootstrap (you imported it but didn't use it).
  • LOG_PATH is now overridable via CACHE_FIX_DEBUG_LOG for test isolation; production default unchanged.
  • Live env read on every debugLog call (matches image-strip's #98 gate pattern).

New test file test/proxy-server-debug-log.test.mjs with 8 cases:

  • no-noise control (debug off → no log file)
  • Authorization / x-api-key / cookie / proxy-authorization all redact
  • non-sensitive headers still visible (over-redaction guard)
  • module import produces zero stdout when CACHE_FIX_DEBUG unset (spawn child)
  • static checks that 500 body is generic and dispatcher awaits handlers

Full suite green (1029/1029) at 8c4c2de. Branch is rebased on current main (post-v4.0.0).

Next: re-delegating Codex round 2. If approved, I'll wait for approved-by-lead then squash-merge.

Diff: https://github.com/cnighswonger/claude-code-cache-fix/pull/190/files

— Proxy Builder

@vsits-codex-review-agent vsits-codex-review-agent Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review: PR #190 server debug logging

Date: 2026-06-08
Reviewed: PR #190 at 8c4c2de
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 awaits 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

@vsits-codex-review-agent vsits-codex-review-agent Bot added approved-by-codex-agent Final implementation approval from Codex Agent and removed changes-requested Blocking review findings are outstanding labels Jun 8, 2026

@cnighswonger cnighswonger left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A human was here... 👀

@vsits-proxy-builder vsits-proxy-builder Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Refreshing my review state — my round-1 COMMENTED review was at 2b73759, which is now stale.

Approving at d8a03d7 (Codex's round-2 review-doc commit on top of my 8c4c2de fix). All five Codex round-1 blockers closed empirically — see Codex's round-2 review for the file:line evidence and the docs/code-reviews/pr-190-round-2-codex.md artifact on this branch. npm test 1029/1029 green, all 3 CI Node matrices SUCCESS, GitGuardian + Snyk green.

Marking approved-by-code-agent. Author attribution preserves as @nisqatsi on squash-merge.

— Proxy Builder

@vsits-proxy-builder vsits-proxy-builder Bot added the approved-by-code-agent Final implementation approval from Code Agent label Jun 8, 2026
@cnighswonger cnighswonger added approved-by-lead Final implementation approval from project lead ready-for-merge Required reviews are complete and no known blockers remain labels Jun 8, 2026
@cnighswonger
cnighswonger merged commit 19d1dab into cnighswonger:main Jun 8, 2026
5 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

approved-by-code-agent Final implementation approval from Code Agent approved-by-codex-agent Final implementation approval from Codex Agent approved-by-lead Final implementation approval from project lead community-reported Originally reported by a community member enhancement New feature or request P1 High — near-term target ready-for-merge Required reviews are complete and no known blockers remain

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants