fix(logging): redact credentials and narrow the notification queue payload

[chrispaskvan]

Refs #711. Deliberately not Closes — the last acceptance criterion is an operational review, not a code change. See Left open.

Two of the issue's three evidence bullets were already fixed by #737: signUp() no longer merges the request body, and the sign-up route already logged allowlisted fields. The rest was live, and the audit turned up more than the issue listed.

What was leaking

Where	What
stdSerializers.req	cookie (session cookie), authorization, x-api-key
stdSerializers.res	set-cookie — the session cookie, on every sign-in
req.url / req.query	GET /users/signIn/Bungie?code=<Bungie OAuth code>&state=…, on the request line
helpers/log.js	no redact configured at all
notification.controller.js	single-recipient path published the whole Cosmos document into Redis — bungie.access_token, refresh_token, membership.tokens.code/.blob
helpers/subscriber.js	spread that payload into its "Processing job" event
user.service.js	logged the whole Twilio message document on delete, including Body — the verification code itself on a verification SMS

Approach

helpers/redact.js holds one list of credential-bearing keys, compiled into Pino redact paths at three depths, plus redactUrl/redactQuery for secrets that live inside a URL string rather than at an object path.

Redaction goes on the root logger, and the alternative was checked rather than assumed: a formatters.log hook runs before the serializers and never sees child bindings, so it could reach neither stdSerializers.req output nor contextMiddleware's per-request child. redact runs after serializers and covers children.

code is not redacted by key — it names a verification code under membership.tokens and a diagnostic (err.code, DestinyError.code) everywhere else. It is censored by position instead: under tokens, and as a query parameter. There is a test asserting err.code survives.

On the queue, Publisher.sendNotification now writes only the three identifiers #send reads. Narrowing in the publisher rather than at the call sites protects the thing that actually needs it — a job outlives the request that created it and is read back by a worker — and the broadcast path was already passing a projection.

Review round 2

@-reviewer found a regression the tests could not catch. Confirmed against main and fixed in 3a7a3b8:

• remoteAddress/remotePort were being dropped. pino-http defaults to wrapSerializers, whose wrapper short-circuits only when the serializer is stdSerializers.req — so the old config was fine and the new one re-serialized an already-serialized object with no socket. The serializer now edits what it is handed, and the spec installs it through wrapRequestSerializer the way pino-http does.
• Redaction cost measured and cut. ~390ns per wildcarded path per line; root keys and spelled-out paths are near free. Restructured into three tiers while widening coverage — measured table below.
• Censor is now REDACTED (no reserved characters), header casing variants added, array limitation documented.

Review round 3 (efbe502)

• A user document was only caught under the key user. Reproduced: { bungieUser: doc } leaked access_token, refresh_token and the verification pair. Fixed by naming the containers — bungie joins tokens as a key censored whole, and user.membership.tokens becomes *.membership.tokens — so the document is caught whatever the call site called it. Replaces three spelled-out paths with two wildcards, so the count moves 36 → 38.
• X-API-Key listed alongside the lower-case spelling.

Cost, measured consistently

60k iterations, sink destination, Node 26:

config	paths	http completion	worker event
no redact	0	~630 ns	~485 ns
first revision (as reviewed)	51	~21,300 ns	~20,500 ns
shipped	38	~7,345 ns	~5,431 ns

Correcting myself: the "~4µs" I quoted in the round-2 comment was measured on a smaller payload from the variant comparison, not on the request-completion event I attributed it to. The honest reduction on that event is ~21.3µs → ~7.3µs, about 2.9x rather than 5x.

What this costs a request

To be unambiguous, since the table above is easy to misread as a regression: 2.9x is the improvement between revisions, not a cost to HTTP performance. Against no redaction at all, the cost is ~6.7µs per log line. The real config writes 2 lines per request, so ~13µs of extra CPU per request.

End to end that is below the noise floor. Three paired runs of 3,000 requests against a route doing no I/O — the worst case, since real endpoints wait on Bungie, Cosmos and Redis:

run	delta
1	−188µs
2	+58µs
3	−18µs

Mean −49µs, i.e. redaction-on measured faster on average. Run-to-run variance (~±190µs) swamps the ~13µs signal entirely. Measurable as CPU, not measurable as latency.

Verification

pnpm test 935 passed / 1 skipped · pnpm lint and pnpm typecheck clean.

Beyond the suite, seven sentinels were driven through the real Express + pino-http + log.js stack under NODE_ENV=production and the captured stdout grepped. None survive. Method, path, status, response time, request id and trace id all remain legible.

That capture is worth calling out, because the unit tests passed while the OAuth code was still leaking. Pino's request serializer also emits Express's parsed req.query, holding the same code as the URL — but a hand-built test request has no query property, so the serializer never copied one and the test asserted about a shape that does not occur in production. redactQuery closes it.

Three mutations were run rather than trusting a green suite:

• redaction depth 3 → 2 failed the two-levels-down, header and child-binding tests
• dropping set-cookie and tokens.blob from the key list failed their tests
• restoring ...newUser to the sign-up log line failed the success-logging test
• rebuilding the serialized request via stdSerializers.req — the regression above — failed the field-set test

Migration

Code path: nothing to do. Jobs already in Redis carry full documents, but #send destructures only the three identifiers so they still process, and the subscriber no longer spreads them into a log line.

Exposure: one deploy step. Corrected after review — "nothing needs draining" was true for correctness and wrong about exposure. removeOnComplete keeps completed jobs 24h and removeOnFail keeps failed ones 7 days, and those retained payloads contain Bungie refresh_tokens. After deploying, clean them out once:

// against the notifications queue
await queue.clean(0, 0, 'completed');
await queue.clean(0, 0, 'failed');

Not baked into startup on purpose — it is a one-time action, and running it on every boot would permanently discard job history that is useful for debugging. Waiting and delayed jobs are deliberately left alone: they are pending sends, they process correctly in the old format, and they age out on their own.

Judgment call worth a second opinion

phoneNumber and displayName are left unredacted on purpose — the consent and claim-check paths log them as the delivery audit trail, and censoring them would blind it. Happy to flip this if you would rather they were censored too.

Left open

Acceptance criterion 6 — reviewing historical log access and retention, and rotating credentials where exposure warrants it. That is operational and yours to make. Given session cookies and OAuth authorization codes were going to logs on every sign-in, it is the criterion I would treat as most urgent.

🤖 Generated with Claude Code

https://claude.ai/code/session_018iD3V7Zyugg3atXVsogTBf

[chrispaskvan]

Thanks — #1 is a real regression and you diagnosed it exactly right. Fixed in 3a7a3b8 along with #2 and the nits.

1. remoteAddress / remotePort — confirmed and fixed

Reproduced against main before touching anything:

main   keys: [headers, id, method, params, query, remoteAddress, remotePort, url]
HEAD   keys: [headers, id, method, params, query, url]

Your read of the mechanism is right: wrapRequestSerializer short-circuits only when the serializer is stdSerializers.req, so the old config never hit the wrapper and the new one re-serialized an object with no socket. Worth noting the evidence was sitting in my own end-to-end capture in the PR description — I checked which sentinels were absent and never checked which fields had gone missing. Absence testing cuts both ways.

Took your patch shape, with one addition. reqSerializer does _req.query = req.query, assigning Express's own object by reference — so an in-place censor would reach the route handler that is about to read req.query.code. The query is replaced with a censored copy rather than written through, and there's a test asserting the live request survives:

serialize(req);
expect(req.query.code).toEqual(code);

The spec now installs the serializer through stdSerializers.wrapRequestSerializer, asserts remoteAddress/remotePort, asserts raw is still reachable through the prototype getter, and compares the full key set against stdSerializers.req's. Mutating it back to the rebuild form fails that last one.

2. Measured — and it reshaped the design

Your ~30x held (Node 26, { write: () => {} } sink, 60k iterations). What the measurement added is where the cost sits: it is per-path, near-constant against payload size, and almost entirely the wildcards.

config	ns/line	paths
no redact	~650	0
depth 1 only	~640	17
depth 2	~8,700	34
depth 3 (as reviewed)	~21,500	51

Root keys are free; each wildcarded path costs ~390ns. So I took your suggestion and split the flat list into three tiers:

• every key at the root — free
• a nestable subset wildcarded one level (the token family only; header names never appear one level down)
• the deep shapes named outright — req.headers.*, res.headers["set-cookie"], user.bungie.*, user.membership.tokens

~21,500ns → ~4,200ns, and coverage got wider, not narrower: tokens is now censored as a whole object, which also covers a join request's tokens.emailAddress — an email verification blob the original by-member paths missed entirely.

3. Retained jobs — you're right, and the PR was wrong

"Nothing needs draining" was true for correctness and wrong about exposure; the "Left open" section did not cover this, so nothing to ignore. removeOnComplete 24h and removeOnFail 7d, with refresh_tokens in the payloads. The Migration section now carries the one-time queue.clean(0, 0, 'completed' | 'failed') as a deploy step.

Not baking it into startup: it is a one-time action, and running it every boot would permanently discard job history. Waiting and delayed jobs are left alone deliberately — they are pending sends, they process correctly in the old format, and they age out.

Nits

• Encoded censor — fixed, REDACTED throughout. The new spec caught this on its own, since it asserts the URL contains censor.
• Case sensitivity — good catch, and verified. Authorization/Cookie added to the root tier and to knownPaths under req.headers.
• Arrays — kept the ceiling, documented the gap. Now stated in the redact JSDoc, specifically that the broadcast path works on user arrays, so users[0].bungie is out of reach at any depth setting.
• Phone numbers — agreed, out of scope here. They are the delivery audit trail in the consent and claim-check paths, so censoring them would blind it. Happy to open a follow-up tied to the retention review.

pnpm test 932 passed / 1 skipped, lint and typecheck clean, and the end-to-end capture re-run: seven sentinels in, none surviving, remoteAddress back.

(Your user.routes.spec failure is environmental as you suspected — Temporal is a global on Node 26, which engines pins.)

🤖 Reviewed with Claude Code · https://claude.ai/code/session_018iD3V7Zyugg3atXVsogTBf

[chrispaskvan]

Both worth addressing, though one of them for a different reason than given. Fixed in efbe502.

1. User documents outside user — you're right, and I'd narrowed it more than I realised

Reproduced exactly as described:

SHIPPED (36 paths)
  log.info({ user })       leaked: none
  log.info({ bungieUser }) leaked: AT,RT,CODE,BLOB

The first revision's wildcards covered this and the retier dropped it. That's on me — I traded it away without noticing it was part of the trade.

Rather than reach for the wildcards again, the fix names the containers instead of the key they hang off:

• bungie joins tokens as a key censored whole, in both tiers
• user.membership.tokens → *.membership.tokens

That replaces three spelled-out paths with two wildcards, so the count goes 36 → 38 and the document is caught whatever it was called:

PROPOSED (38 paths)
  log.info({ bungieUser }) leaked: none
  log.info({ registered }) leaked: none

Parameterised over three key names, and removing either new path fails it. Censoring the container also means a field added to bungie later is covered without this list being revisited — same reasoning that already applied to tokens.

On the suggested spec — a test asserting no log.* call passes a whole user object — I've left it out. It would have to pattern-match source text, and it can't distinguish log.info({ user }) from log.info({ user: user.id }) without real parsing; a regex that tried would either miss the second or fail on the first. The container fix removes most of what it would have been guarding, and the remaining rule is stated in the JSDoc. Happy to revisit if you see a non-brittle shape for it.

2. X-API-Key — added, but the premise doesn't hold

Added it, so the outcome is what you wanted. But I checked before taking the reason, and it isn't right for this codebase: all eight Bungie call sites write lower-case.

destiny/destiny.service.js:116,176,234,270    'x-api-key': apiKey,
destiny2/destiny2.service.js:71,126,201,274   'x-api-key': apiKey,

So it isn't inconsistent with the Authorization rationale — bitly.js:34 and mms.service.js:216 really do write capital Authorization, which is why both casings were listed there. Nothing here writes X-API-Key.

It's in anyway, because it's Bungie's documented spelling, a root-tier key is free, and someone copying from those docs would write it that way. I've rewritten the JSDoc to state the rule the list actually follows rather than implying this codebase writes that casing.

Correcting a number I published

The "~4µs" in my round-2 comment was measured on a smaller payload from the variant comparison, not on the request-completion event I attributed it to. Measured consistently:

config	paths	http completion	worker event
no redact	0	~630 ns	~485 ns
first revision (as reviewed)	51	~21,300 ns	~20,500 ns
shipped	38	~7,345 ns	~5,431 ns

~21.3µs → ~7.3µs, about 2.9x rather than the 5x I implied. The conclusion holds and the tiering still earns its place, but the figure was wrong and it was in the PR body too, now corrected.

pnpm test 935 passed / 1 skipped, lint and typecheck clean.

🤖 Reviewed with Claude Code · https://claude.ai/code/session_018iD3V7Zyugg3atXVsogTBf