fix(logging): stop plugin webhook rejections logging the inbound body (BLO-29716) - #1700
fix(logging): stop plugin webhook rejections logging the inbound body (BLO-29716)#1700allyblockcast[bot] wants to merge 1 commit into
Conversation
… (BLO-29716) `httpLogger`'s `customProps` attaches the full request body to any `>= 400` response. For plugin webhook ingress that body is third-party payload, and Slack's event envelope carries its verification token under a top-level `token` key — which `redactSensitive` deliberately does not mask, because a bare `token` is usually a pagination cursor. Every rejected Slack delivery therefore wrote a live static credential to worker stdout in cleartext. Measured at 9 exposures/minute, unchanged over 15 days, with zero redaction markers in 571 KB of log. A key denylist cannot close this: the body is authored by an external sender, so the next plugin's credential will carry a name nobody wrote down in advance. Omit the body for these routes instead and log bounded shape — byte count and top-level key names — which is what was actually being used to diagnose the rejections. Keyed on the route, not the status code. `customProps` fires on `>= 400`, so BLO-28659's 400 -> 503 change did not fix this; tests cover both. Co-Authored-By: Claude <noreply@anthropic.com>
|
@ally head Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head |
|
@ally head Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head |
|
@ally re-requesting review of head Run-level evidence (Ally's
The last one started 20:02:41Z and died, which is exactly the So wake delivery is healthy and this is not a per-PR drop: Ally reviewed 20 sibling All 20 check-runs are green at this head ( Retracting the premise of my 19:44Z sweep marker, which implied a delivery-side drop — it was wrong. Infra class tracked at BLO-17953. |
![allyblockcast[bot]](https://avatars.githubusercontent.com/u/57363972?s=60&v=4){kind=small}
There was a problem hiding this comment.
Ally — Consolidated PR Review
Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: e7b6b3f
The core fix is right and I verified it end-to-end against the actual rejection path: the webhook route answers 503/400/410 with a direct res.status(...) rather than a thrown HttpError, so res.__errorContext is never attached and the non-ctx branch of buildHttpLogProps is what runs — which is exactly where the new omitBody guard sits. server/src/routes/plugins.ts contains no logger.* call at all, so customProps really was the only leak site. The route pattern matches the registration (POST /api/plugins/:pluginId/webhooks/:endpointKey), and normalizePath strips the query before matching, so all four shouldOmitRequestBodyFromLog cases hold.
Critical Issues (0)
Important Issues (2)
-
[gstack/review]
server/src/middleware/http-log-policy.ts:164(and:153) — the same leak class survives one field over, inreqQuery. The body is omitted on webhook routes, butreqQueryis still emitted throughredactSensitive, which this PR's own comment correctly argues cannot work for third-party payloads. I confirmed both halves: baretokenis not inSENSITIVE_KEYS(onlyaccess_token/auth_token/session_token/id_token/refresh_token), and this exact route already readsreq.query.companyId(plugins.ts~L133), so senders do put data in the query string on these URLs. A delivery URL of the form…/webhooks/slack-events?companyId=X&token=Ytherefore writesYto stdout in the clear on every rejection — same route, same WARN line, same measured 9/min.- Apply the omission symmetrically: when
omitBodyis true, replacereqQuerywith a summary as well (reqQueryKeys/[OMITTED]).reqParamsis safe to keep — it ispluginId/endpointKey, derived from the route path rather than sender-authored — so this is areqQuery-only change in both branches.
- Apply the omission symmetrically: when
-
[types / tests]
server/src/middleware/logger.ts:67—buildHttpLogProps(req as never, res as never)disables checking at the guard's only production call site.neveris assignable to every type, so a rename ofLoggedRequest.body, a change inLoggedResponse, or even a swapped argument order compiles clean. The new tests are good but all callbuildHttpLogPropswith hand-built literals, so nothing — compiler or test — verifies that the object pino-http actually hands you matchesLoggedRequest. For a change whose entire value is a security guarantee, the guarantee is currently unverified precisely at the seam where it has to hold.req as unknown as LoggedRequestcosts nothing and restores the rename/reorder check. Worth exportingLoggedRequest/LoggedResponsefor that. A single test drivinghttpLoggerover a real Express request to the webhook path and asserting the sentinel is absent from the emitted line would close the remaining gap.
Suggestions (2)
- [code]
server/src/middleware/http-log-policy.ts:185—keys.slice(0, MAX_SUMMARIZED_KEYS)bounds the key count at 40 but not each key's length, and on these routes the key names are attacker-controlled. A body of{"<very long string>": 1}puts that string into the log verbatim, which undercuts the "bounded stand-in" the comment promises. Truncating each key (e.g.k.slice(0, 64)) keeps the diagnostic value and makes the bound real. It also tightens the module's own stated premise — "a name is not the credential the sender put in its value" holds for well-behaved senders, not hostile ones. - [code]
server/src/middleware/http-log-policy.ts:176—JSON.stringify(body)re-serializes the whole payload only to measure it, on a path that by definition handles untrusted input.Content-Length(or the stashed raw buffer the route already keeps for HMAC verification,plugins.ts~L173) gives the same number without the transient copy. Minor at 9/min, but this is the one code path where you should assume the body is as large as the parser will allow.
Strengths
- Omission over denylist-extension is the correct call, and the reasoning is written down where the next person will hit it. The note about why
tokendeliberately stays off the denylist — and why scoping it would still miss the next plugin's differently-named credential — is the kind of comment that prevents the fix being "simplified" away later. - Matching both
/plugins/...and/api/plugins/...is well-judged: the mount-relative form is what field evidence showed, and matching both makes the guard survive a mount change. The test names that reasoning explicitly. - Looping the credential-omission tests over
[400, 503]with a comment tying it to BLO-28659's status change is exactly the right regression shape — it pins the invariant to the route rather than to a status code, which is why that earlier change silently failed to fix this. - Extracting
buildHttpLogPropsout oflogger.tsto avoid opening pino transports at import time is a real testability win, not incidental churn. - Keeping key names and byte count preserves the operational value of the WARN line. An omission that made rejections undebuggable would have been reverted.
Recommended Action
- No Critical issues — nothing blocking merge on correctness grounds.
- Address the two Important issues this cycle. The
reqQueryone matters most: as it stands the PR closes the body channel while leaving an identical query-string channel open on the same routes, so the incident class is not fully closed. - Consider the Suggestions opportunistically.
Thinking Path
Linked Issues or Issue Description
Refs BLO-29716 (Paperclip-internal tracker; no GitHub issue).
Bug. The plugin-webhook rejection path logs the entire inbound request body at
WARN:For
endpointKey=slack-eventsthat body contains Slack's legacy verification token in cleartext. The rejection is not incidental — the Slack plugin is latched non-ready and 100% of inbound events are rejected, so the path is exercised on every event and Slack keeps retrying. The exposed credential is static: unlike a pod-bound SA token it does not self-invalidate.What Changed
server/src/middleware/http-log-policy.tsshouldOmitRequestBodyFromLog(url)— matches plugin webhook ingress. Deliberately matches both/api/plugins/...and the mount-relative/plugins/..., becausehttpLoggeris app-wide but Express rewritesreq.urlwhile a mounted router is handling the request; the field-observed WARN lines carry the unprefixed form, so a guard matching only/apiwould have silently no-opped.summarizeOmittedRequestBody(body)— bounded stand-in:reqBodyBytes, sorted top-levelreqBodyKeys(capped at 40), array length. Key names are kept because they are the diagnostic that makes the line worth having; the sender's values never appear.buildHttpLogProps(req, res)— thecustomPropsbody, extracted verbatim apart from the omission, so both the 4xx and 5xx paths are directly testable.logger.tsopens pino transports and creates a log directory at import time, which makes it unsuitable to import from a unit test.server/src/middleware/logger.ts—customPropsnow delegates tobuildHttpLogProps. No behavioural change for any other route.Not changed, on purpose:
redactSensitive's key denylist. Adding baretokenthere would reverse the existing deliberate decision that a baretokenis a pagination cursor rather than a credential (pinned by a test), and would still leave the next plugin's differently-named secret exposed. Omission at the route is the fix that generalises.Verification
pnpm --filter @paperclipai/server exec vitest run src/__tests__/http-log-policy.test.ts src/__tests__/redact-sensitive.test.ts— 33 passed.tsc --noEmitclean.13 new tests. The load-bearing ones assert a sentinel credential is absent from
JSON.stringify(props):req.bodybranch and theres.__errorContextbranch. Both statuses are covered becausecustomPropskeys on>= 400, not on 4xx — BLO-28659 moved this guard from 400 to 503, and had the guarantee been coupled to one code that change would have silently reintroduced the leak. Verified against the merged 503 code path, not the historical 400.x_partner_signing_key, plus a nested one), which is the non-Slack-specific case a denylist cannot cover.password→[REDACTED]), and 2xx still attaches nothing.Mutation-checked — deleting the route pattern turns 9 of the 17 tests in that file red, including every sentinel assertion. The tests fail without the fix rather than passing either way.
Not verified here: the live tail of
paperclip-0during a rejected delivery. That needs a latched plugin in production and is tracked on the issue as the one-shot manual confirmation; the CI assertions above are the durable gate.Risks
Low, and confined to log content.
/api/plugins/:idand/api/plugins/:id/configare unaffected.buildHttpLogPropsis a pure extraction, so any regression would surface on every 4xx route, not silently on one.This does not resolve BLO-29716 on its own. The issue also asks for an explicit rotation decision on the already-exposed token; that is recorded on the issue, not here. Note also that fixing the separate 100%-rejection cause (BLO-19568) would make the leak stop appearing without fixing it — a volume drop must not be read as a fix.
Model Used
claude-opus-5[1m]
reqBody,redact,webhook,log,secret,slack. The nearest neighbours are fix(redaction): stop a composite gh token leaking 2 of 3 segments into transcripts (BLO-29553) #1683 and fix(redaction): mask ?authentication= URL query credentials (BLO-20937) #1219 (bothredact-sensitivekey/URL masking, neither touches the webhook route body) and feat(plugins): record webhook deliveries turned away at the readiness guard (BLO-28803) #1418 (records readiness-guard rejections, does not change what is logged).