Skip to content

Structured JSON logging with correlation IDs across request lifecycle - #1072

Merged
joelpeace48-cell merged 8 commits into
FinesseStudioLab:mainfrom
Armolas:feat/925-structured-logging-correlation-ids
Jul 29, 2026
Merged

Structured JSON logging with correlation IDs across request lifecycle#1072
joelpeace48-cell merged 8 commits into
FinesseStudioLab:mainfrom
Armolas:feat/925-structured-logging-correlation-ids

Conversation

@Armolas

@Armolas Armolas commented Jul 29, 2026

Copy link
Copy Markdown
Contributor

Summary

Closes #925. Pino was already wired up for structured JSON logging, and a requestId middleware already existed — but correlation IDs never made it past the access-log line into jobs, RPC calls, or business-logic logs, and there was no secret redaction at all. This PR closes those gaps.

What's new

Correlation context

  • New AsyncLocalStorage-based correlation context (backend/src/lib/requestContext.js) so any code in a request or job's call chain can read the current correlation ID without threading it through every function signature.
  • Wired into pino via a mixin — every log.*() call automatically picks up requestId from the active context, no call site needs to remember to pass it.
  • X-Request-Id added to CORS allowed/exposed headers so cross-origin clients can read and supply it.

Propagation to jobs + RPC

  • Both jobRunner (in-memory) and durableJobQueue (SQLite-backed) capture the enqueuing request's correlation ID and re-establish it as context when the job actually runs, so job logs — including retries — tie back to the request that triggered them.
  • The durable queue persists the ID on the job row (migration 035) so it survives a process restart.
  • rpcPool.js and sorobanRpc.js had zero logging before this PR. Added structured log lines for circuit-breaker transitions, pool saturation, endpoint health changes, and RPC success/failure/latency — all correlated via the outbound x-request-id header and log context.

No secret leakage

  • Added a pino redact config stripping API keys, auth headers, passwords, and tokens by convention (previously none existed).

Cleanup (blocking "all logs are structured")

  • Fixed ~26 call sites where log.X('message', {fields}) was silently dropping the fields object — pino's real argument order is (fields, message), verified empirically. Affected status.js, webhooks.js, faucet.js, pruningJob.js.
  • Migrated routes/variants.js and routes/audit.js off raw console.error onto the structured logger.

Bugs found along the way

Tightening checkSorobanRpcHealth's typing (needed for correct test coverage) surfaced two compounding pre-existing bugs in routes/status.js: it called the health check with no rpcUrl (always fetching undefined), and treated the returned result object — always truthy, even on status: 'error' — as a boolean. Net effect: the public status page's RPC component permanently reported "operational" regardless of actual health. Fixed both.

Testing

~60 new/extended tests across lib/requestContext, middleware/requestContext, middleware/requestId (previously untested), middleware/logger (mixin + redact verified against a real pino instance, not mocked), jobRunner, durableJobQueue, rpcPool, sorobanRpc, and index.test.js integration tests.

Live end-to-end smoke test: booted the real backend and confirmed a client-supplied X-Request-Id header shows up correlated across the access log, RPC log, and response headers; confirmed job retries share a consistent correlation ID across attempts; confirmed an Authorization header never leaks into logs.

eslint/tsc --noEmit clean on all touched files (pre-existing, unrelated warnings/errors elsewhere untouched).

Acceptance criteria

  • All logs are structured + correlated.
  • IDs propagate to jobs + RPC.
  • No secret leakage in logs.

Armolas added 8 commits July 29, 2026 08:22
Framework-agnostic core (lib/requestContext.js) plus a thin Express
adapter. Lets any code in a request or job's call chain read the
current correlation ID without threading it through every function
signature.
…sseStudioLab#925)

pino mixin auto-injects requestId into every log line via the new
context; redact config strips API keys/auth headers/passwords by
convention. requestContextMiddleware mounted right after requestId in
index.js. X-Request-Id added to CORS allowed/exposed headers so
cross-origin clients can read and supply it. Adds the requestId.test.js
unit coverage that didn't previously exist.
Both jobRunner (in-memory) and durableJobQueue (SQLite-backed) capture
the enqueuing request's correlation ID and re-establish it as context
when the job actually runs, so job logs — including retries — tie back
to the request that triggered them. The durable queue persists the ID
on the job row (migration 035) so it survives a process restart.
Job logs switched from interpolated strings to structured objects.
…inesseStudioLab#925)

rpcPool.js and sorobanRpc.js had zero logging before this. Adds
structured log lines for circuit-breaker transitions, pool saturation,
endpoint health changes, and RPC success/failure/latency, all
correlated via the outbound x-request-id header and log context.

Also fixes two compounding pre-existing bugs found via stricter typing
on checkSorobanRpcHealth: routes/status.js called it with no rpcUrl
(always fetching undefined) and treated its returned result object —
always truthy, even on status: 'error' — as a boolean, so the status
page permanently reported the RPC component as operational.
…log (FinesseStudioLab#925)

log.X('message', {fields}) silently drops the fields object with
pino's real argument order (fields first, message second) — verified
empirically. Fixes ~26 such call sites across status.js, webhooks.js,
faucet.js, and pruningJob.js, and migrates routes/variants.js and
routes/audit.js off raw console.error onto the structured logger.
Integration-level coverage: X-Request-Id generation/echo/uniqueness,
CORS exposure, and that the access-log line carries the same ID
returned to the client.
…flict)

PR_DESCRIPTION.md and pr_description.md were both tracked with the
same content family, which is unrepresentable on case-insensitive
filesystems and made every checkout/rebase spuriously dirty. Keeping
only the uppercase path.
…-logging-correlation-ids

# Conflicts:
#	backend/src/jobs/jobRunner.test.js
@drips-wave

drips-wave Bot commented Jul 29, 2026

Copy link
Copy Markdown

@Armolas Great news! 🎉 Based on an automated assessment of this PR, the linked Wave issue(s) no longer count against your application limits.

You can now already apply to more issues while waiting for a review of this PR. Keep up the great work! 🚀

Learn more about application limits

@joelpeace48-cell
joelpeace48-cell merged commit ba2fb96 into FinesseStudioLab:main Jul 29, 2026
4 of 15 checks passed
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.

Structured logging with correlation IDs across request lifecycle

2 participants