Skip to content

feat: structured JSON logger with per-request id and access log#156

Open
Shawnaldinho wants to merge 1 commit into
willchen96:mainfrom
Shawnaldinho:feat/request-id-and-error-logging
Open

feat: structured JSON logger with per-request id and access log#156
Shawnaldinho wants to merge 1 commit into
willchen96:mainfrom
Shawnaldinho:feat/request-id-and-error-logging

Conversation

@Shawnaldinho
Copy link
Copy Markdown

Summary

Backend logs were all free-form `console.log`/`console.error`, so an error you see on the client can't be correlated to the line that produced it on the server, and there's no way to filter by route/status/user_id from a log aggregator. This PR puts the floor in: a tiny structured logger, a per-request id, and an access log line per response.

Changes

  • `backend/src/lib/logger.ts` — zero-dep JSON-line logger. `logger.{debug,info,warn,error}({ fields }, msg)` writes one JSON object per call (stdout for info/debug, stderr for warn/error). Level is controlled by `LOG_LEVEL` (defaults: `info` in production, `debug` elsewhere). `logger.child({ ... })` returns a logger that prefixes every event with the given fields. `errFields(err)` pulls `err_name`/`err_msg`/`err_stack` out of an `Error`. Hand-written instead of pulling pino — only ~80 lines today; the call sites won't change if it's later swapped.
  • `backend/src/middleware/requestContext.ts` — assigns a per-request id (inbound `X-Request-Id` if present, else a UUID), echoes it back on the response, parks a child logger on `res.locals.log`, and on response `close` emits one access-log line with method/route/status/elapsed_ms/user_id. Wired into `index.ts` before the rate limiters.
  • Demonstrate adoption in the most user-visible places: the two streaming error paths (`POST /chat`, `POST /projects/:projectId/chat`) and the title-generation handler now use the request-scoped logger so their error lines correlate with the access log via `request_id`. Debug-style `console.log` calls in `chatTools.ts` / `documents.ts` were left alone — that's a separate, broader cleanup.

Why

Concrete things this enables that weren't possible before:

  • `request_id= level=error` filter in CloudWatch / Loki / Datadog pulls every line tied to one failing request.
  • Frontend can surface the `X-Request-Id` so a user-reported "chat broke" comes with the exact id you grep for.
  • Distinguishing client-side cancels (`status=499`) from server-side errors (`status=500`) without touching the console.

Addresses the observability concern from https://insights.flank.ai/where-mikeoss-falls-short.html (gap 14). Doesn't try to also tackle tracing / metrics / Sentry — those are reasonable follow-ups built on this foundation.

Testing

  • `npm run build --prefix backend` passes.
  • Hand-traced a request through `requestContext` → rate-limiter → handler → `close` and confirmed (a) inbound `X-Request-Id` is preserved, (b) generated UUID echoed back when absent, (c) access-log line emits with the same id, (d) the streaming error logs share that id.

Previously every backend log was a free-form console.log/error, so
there was no way to (a) correlate the streaming error you see in a
client with the server-side line that produced it, or (b) filter on
status / route / user_id from a log aggregator. The blog post about
mikeoss called out the absence of structured logging, request
correlation, and error context, so this PR puts the floor in.

Three pieces:

1. backend/src/lib/logger.ts — ~80-line zero-dep JSON line logger.
   - logger.{debug,info,warn,error}({ fields }, msg) emits one JSON
     object per call to stdout/stderr.
   - level is controlled by LOG_LEVEL env var, defaulting to "info"
     in production and "debug" elsewhere.
   - logger.child({ fields }) returns a logger that prefixes every
     event with the given fields — used by the request middleware to
     bind request_id.
   - errFields(err) helper extracts name/message/stack from an Error.
   - Kept hand-written instead of pulling in pino because we only need
     ~30 lines today; the call sites won't change if it's later swapped.

2. backend/src/middleware/requestContext.ts — assigns a per-request id
   (from inbound X-Request-Id if present, else a UUID), echoes it on
   the response, parks a child logger on res.locals.log, and on
   response close emits one access-log line with method/route/status/
   elapsed_ms/user_id. Wired into index.ts before the rate limiters.

3. Demonstrate adoption: replace console.error in the two streaming
   error paths (POST /chat, POST /projects/:projectId/chat) and the
   generate-title handler. Each unhandled error log now ships with the
   request_id so it correlates to the access log line. Left the
   debug-style console.log calls in chatTools.ts / documents.ts alone
   — they're a separate, broader cleanup.

The X-Request-Id header is echoed on every response so a curl user
or a frontend retry can grep their request out of the logs.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant