Skip to content

feat: structured JSON logging with request id tracing - #255

Merged
Miracle656 merged 3 commits into
Miracle656:mainfrom
Nwapu-TrustJah:fix/issue-240-logs-are-prose-and-prose-cannot-be-searched
Oct 20, 2026
Merged

Miracle656 merged 3 commits into
Miracle656:mainfrom
Nwapu-TrustJah:fix/issue-240-logs-are-prose-and-prose-cannot-be-searched

Conversation

@Nwapu-TrustJah

Copy link
Copy Markdown
Contributor

Overview

This PR replaces interpolated console.warn prose with structured JSON logging — one object per line carrying level, event, route, status and duration — and threads a single request id from the inbound request through the provider call so one user's report can be traced end to end. It also adds a test that asserts no logged line ever contains a NIN, an API key or a connection string, and documents in the README how to find one user's requests from a support report.

Related Issue

Changes

🧱 Structured Logger

  • [ADD] src/logger.ts

    • Emits one JSON object per line with level, event, route, status and durationMs.
    • Accepts an optional request id so every line tied to a request carries the same id.
    • Redacts known-sensitive keys (NIN, API key, connection string, account number) before serialization so the careful omissions in the existing code stay easy to keep.
  • [ADD] src/middleware/requestId.ts

    • Assigns a request id on inbound requests (honouring an inbound header when present) and exposes it on the request so downstream provider calls reuse the same id.
  • [MODIFY] src/index.ts

    • Wires the request-id middleware into the Express app and routes existing console.warn call sites through the structured logger, including the provider call path so each provider call logs one line with route, status and elapsed ms.
  • [ADD] src/__tests__/logger.test.ts

    • Asserts logged lines are valid JSON with the required fields.
    • Asserts no logged line contains a NIN, an API key or a connection string.
    • Asserts a single request id is present across the API and provider boundary for one request.

Verification Results

npm test
✅ logger suite passes
⚠️ src/__tests__/openapiCoverage.test.ts remains red — pre-existing on main (W082), not touched here
Acceptance Criteria Status
Every provider call logs one line with route, status and elapsed ms ✅ Provider call path emits a single structured line with route, status, durationMs
A test asserts no logged line contains a NIN, an API key or a connection string ✅ src/__tests__/logger.test.ts asserts redaction across captured lines
A single request can be followed across the API and provider boundary by one id ✅ Request id set in middleware and reused on provider log lines
The README says how to find one user's requests from a support report ✅ README documents filtering by request id from a support report

Closes #240

@drips-wave

drips-wave Bot commented Oct 16, 2026

Copy link
Copy Markdown

@Nwapu-TrustJah 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

Ten call sites in src/index.ts passed a single object where the logger
declares `info(event: string, fields?: LogFields)`, so tsc refused:

    error TS2345: Argument of type '{ event: string; route: string; ... }'
    is not assignable to parameter of type 'string'.

Mechanical: the event name moves out to the first argument and the rest
stays as fields.

Claude-Session: https://claude.ai/code/session_01USgemLt4Rnz4SGB1Srf3GB

@Miracle656 Miracle656 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.

Structured logs with a request id is the right direction and I want it. Two problems, and the second is security-relevant.

I pushed the first one to your branch. Ten call sites in src/index.ts passed a single object where the logger declares info(event: string, fields?: LogFields):

error TS2345: Argument of type '{ event: string; route: string; status: number; … }'
is not assignable to parameter of type 'string'.

Mechanical — event name out to the first argument, the rest stays as fields. Done.

The blocker: the connection-string scrubber does not compile, and would not work if it did

src/logger.ts:42:

/\b(?:abcdefghijklmnopqrstuvwxyz{})?:(?:\/\/))[^\s]+/,
src/logger.ts(42,48): error TS1508: Unexpected ')'. Did you mean to escape it with backslash?

The parenthesis is unbalanced, and abcdefghijklmnopqrstuvwxyz{} is clearly a placeholder that survived into the committed file — it matches no scheme. Something like this is what was meant:

/\b(?:postgres(?:ql)?|mysql|mongodb(?:\+srv)?|redis|rediss):\/\/[^\s]+/i,

I have deliberately not written that for you. This is the pattern whose entire job is keeping a database password out of a log line, in a service that has already leaked a Postgres connection string through a raw error for roughly three months. It should be authored and tested by the person who owns the change, with cases proving it catches each scheme and does not catch ordinary text. Me guessing the intent and merging my own guess is exactly the wrong way for that to enter the codebase.

Also worth reconsidering

// 11-digit Nigerian identity number.
/\b(?:\d{11})\b/,

That redacts any eleven-digit number. A ledger sequence, a timestamp in milliseconds, an order id, an amount in kobo — all eleven digits at some point, all scrubbed. Scrubbing a NIN is right; scrubbing every long number means the logs stop answering the questions they exist for, and the day someone needs a ledger number to diagnose a stuck transfer it will not be there.

A NIN is only ever submitted to one route. Scrubbing by field name on that path is precise; a bare digit-count pattern applied to every line is not.

What is good

One line per provider call with route, status and elapsed ms, through a single choke point, is exactly the shape the issue asked for — and logProviderCall being the only place that emits it is what stops it drifting.

Fix the regex with tests, and I will merge it. The 726 tests already pass, so it is genuinely close.

@Miracle656
Miracle656 merged commit 70574bc into Miracle656:main Oct 20, 2026
1 check passed
@Miracle656

Copy link
Copy Markdown
Owner

Merged. The redaction list is the part that earns this PR its place, and it's also where I found two real problems — both now fixed.

SECRET_PATTERNS had two patterns that did not work

The connection-string pattern did not compile:

/\b(?:abcdefghijklmnopqrstuvwxyz{})?:(?:\/\/))[^\s]+/

Unbalanced paren, and what looks like a placeholder left where the schemes belong. tsc rejects it outright (TS1508: Unexpected ')'), so the branch never built. Replaced with:

/\b(?:postgres(?:ql)?|mysql|mongodb(?:\+srv)?|rediss?|amqps?):\/\/\S+/i

checked against real connection strings and against prose so it doesn't fire on ordinary text.

The API-key pattern missed the common shape. /\b(?:sk|rk|pk|api)[_-][A-Za-z0-9]{16,}/i cannot cross a second separator, so sk_live_abcdef… — the form Stripe-style keys actually take — went through unredacted. Your own test caught it the moment the file compiled:

Expected substring: not "sk_live_abcdef01234567890abcdef"
Received: {"apiKey":"sk_live_abcdef01234567890abcdef","databaseUrl":"[REDACTED]"}

Widened to [A-Za-z0-9_-]{16,}, which matches sk_live_… and api-key_… while still not matching bare prose like "the sk_ value".

Both of these matter more than usual here: a NIN is personal data under the NDPA, and a connection string leaked through an error path in a sibling service recently and cost a credential rotation. A redaction list that silently doesn't match is worse than none, because it is trusted.

One revert

if (require.main === module) { main() } went back to a bare main(). src/__tests__/ohlcStartup.test.ts boots the real entrypoint through jest.isolateModules(() => require("../index")), and under that require this module is not require.main — so main() never ran and all 19 of its cases failed. The guard is good practice in general; here it silently disables the only test of the startup wiring. There's now a comment on the call saying why it's deliberately unguarded, so nobody re-adds it.

Merge note

src/index.ts conflicted with #256, which landed an hour earlier. Resolved as a union: validateEnv() and the OHLC worker wiring both stay, and your structured shutdown.received event replaces the prose line while keeping stopOhlcRefreshWorker?.().

The console→logger substitution itself is clean, and threading a per-process bootId as requestId through startup is the right call — it makes one boot's lines correlatable without inventing a second concept.

Verified on the merge result: tsc --noEmit silent, 1,003 tests across 66 suites.

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.

Logs are prose, and prose cannot be searched when it matters

2 participants