From e7b6b3f618d7de5d7dd52c7c88b6f5e0e96d53c1 Mon Sep 17 00:00:00 2001 From: CTO Date: Mon, 7 Sep 2026 06:05:26 +0000 Subject: [PATCH 1/2] fix(logging): stop plugin webhook rejections logging the inbound body (BLO-29716) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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 --- server/src/__tests__/http-log-policy.test.ts | 105 ++++++++++++++++- server/src/middleware/http-log-policy.ts | 117 +++++++++++++++++++ server/src/middleware/logger.ts | 31 +---- 3 files changed, 223 insertions(+), 30 deletions(-) diff --git a/server/src/__tests__/http-log-policy.test.ts b/server/src/__tests__/http-log-policy.test.ts index 0e540a111614..7c9bea8a2c03 100644 --- a/server/src/__tests__/http-log-policy.test.ts +++ b/server/src/__tests__/http-log-policy.test.ts @@ -1,5 +1,5 @@ import { describe, expect, it } from "vitest"; -import { shouldSilenceHttpSuccessLog } from "../middleware/http-log-policy.js"; +import { buildHttpLogProps, shouldOmitRequestBodyFromLog, shouldSilenceHttpSuccessLog } from "../middleware/http-log-policy.js"; describe("shouldSilenceHttpSuccessLog", () => { it("silences cached 304 responses", () => { @@ -71,3 +71,106 @@ describe("shouldSilenceHttpSuccessLog", () => { expect(shouldSilenceHttpSuccessLog("GET", "/@fs/Users/dotta/paperclip/ui/src/main.tsx", 404)).toBe(false); }); }); + +// BLO-29716: plugin webhook rejections logged the whole inbound body at WARN. +// Slack's event envelope carries its verification token under a top-level +// `token`, so a live static credential was written to worker stdout on every +// rejected delivery (measured at 9/minute, 15 days running). +describe("shouldOmitRequestBodyFromLog", () => { + it("omits the body for plugin webhook ingress", () => { + expect(shouldOmitRequestBodyFromLog("/api/plugins/slack/webhooks/slack-events")).toBe(true); + }); + + it("omits it on the mount-relative path too, which is the form actually logged", () => { + // httpLogger is app-wide but Express rewrites req.url while a mounted + // router is handling the request; the WARN lines on BLO-29716 show + // `/plugins/...`. A guard matching only the `/api` form would no-op. + expect(shouldOmitRequestBodyFromLog("/plugins/slack/webhooks/slack-events")).toBe(true); + }); + + it("ignores the query string when matching", () => { + expect(shouldOmitRequestBodyFromLog("/plugins/slack/webhooks/slack-events?companyId=abc")).toBe(true); + }); + + it("leaves ordinary routes logging their bodies", () => { + expect(shouldOmitRequestBodyFromLog("/api/issues/BLO-1")).toBe(false); + expect(shouldOmitRequestBodyFromLog("/api/plugins/slack")).toBe(false); + expect(shouldOmitRequestBodyFromLog("/api/plugins/slack/config")).toBe(false); + expect(shouldOmitRequestBodyFromLog(undefined)).toBe(false); + }); +}); + +describe("buildHttpLogProps — no credential reaches a rejection log line", () => { + const SENTINEL = "xoxb-sentinel-verification-token-do-not-log"; + const slackBody = { + token: SENTINEL, + type: "event_callback", + team_id: "T123", + event: { type: "message", text: "hi" }, + }; + + // Both statuses are exercised because customProps keys on `>= 400`, not on + // 4xx. BLO-28659 moved the readiness guard from 400 to 503; if the guarantee + // were coupled to one status code that change would have silently + // reintroduced the leak. It must hold on whichever code the guard returns. + for (const statusCode of [400, 503]) { + it(`omits the Slack verification token on a ${statusCode} rejection`, () => { + const props = buildHttpLogProps( + { url: "/plugins/slack/webhooks/slack-events", body: slackBody }, + { statusCode }, + ); + + expect(JSON.stringify(props)).not.toContain(SENTINEL); + expect(props.reqBody).toBe("[OMITTED: untrusted webhook payload]"); + }); + + it(`omits it on the ${statusCode} error-handler path as well`, () => { + // The error handler stashes its own copy on res.__errorContext; that is + // a second branch and needs the same guard. + const props = buildHttpLogProps( + { url: "/plugins/slack/webhooks/slack-events" }, + { statusCode, __errorContext: { error: { message: "boom" }, reqBody: slackBody } }, + ); + + expect(JSON.stringify(props)).not.toContain(SENTINEL); + expect(props.reqBody).toBe("[OMITTED: untrusted webhook payload]"); + }); + } + + it("is not Slack-specific: an arbitrarily-named credential is omitted too", () => { + // The point of omitting rather than denylisting. `x_partner_signing_key` + // is on no list and never will be, because the next plugin invents it. + const props = buildHttpLogProps( + { + url: "/plugins/acme/webhooks/inbound", + body: { x_partner_signing_key: SENTINEL, nested: { also_secret: SENTINEL } }, + }, + { statusCode: 503 }, + ); + + expect(JSON.stringify(props)).not.toContain(SENTINEL); + }); + + it("keeps the rejection debuggable — size and shape, never values", () => { + const props = buildHttpLogProps( + { url: "/plugins/slack/webhooks/slack-events", body: slackBody }, + { statusCode: 503 }, + ); + + expect(props.reqBodyKeys).toEqual(["event", "team_id", "token", "type"]); + expect(props.reqBodyBytes).toBe(Buffer.byteLength(JSON.stringify(slackBody), "utf8")); + }); + + it("still logs and redacts bodies on non-webhook routes", () => { + const props = buildHttpLogProps( + { url: "/api/auth/sign-in/email", body: { email: "a@b.co", password: "hunter2" } }, + { statusCode: 400 }, + ); + + expect(props.reqBody).toEqual({ email: "a@b.co", password: "[REDACTED]" }); + }); + + it("logs nothing extra for a successful response", () => { + expect(buildHttpLogProps({ url: "/plugins/slack/webhooks/slack-events", body: slackBody }, { statusCode: 200 })).toEqual({}); + }); +}); diff --git a/server/src/middleware/http-log-policy.ts b/server/src/middleware/http-log-policy.ts index a0b93694b229..a05fc3e84192 100644 --- a/server/src/middleware/http-log-policy.ts +++ b/server/src/middleware/http-log-policy.ts @@ -1,3 +1,5 @@ +import { redactSensitive } from "./redact-sensitive.js"; + const SILENCED_SUCCESS_METHODS = new Set(["GET", "HEAD"]); const SILENCED_SUCCESS_API_PATHS = [ @@ -48,3 +50,118 @@ export function shouldSilenceHttpSuccessLog(method: string | undefined, url: str if (SILENCED_SUCCESS_STATIC_PREFIXES.some((prefix) => pathname.startsWith(prefix))) return true; return SILENCED_SUCCESS_API_PATHS.some((pattern) => pattern.test(pathname)); } + +// Routes whose request body is third-party payload and must never be logged, +// redacted or otherwise (BLO-29716). +// +// `redactSensitive` is a denylist of key *names*. That works for our own +// routes, where somebody can write the credential-bearing names down in +// advance. It cannot work for plugin webhook ingress: the body is arbitrary +// JSON authored by an external sender. Slack's event envelope carries its +// verification token under the top-level key `token`, which is deliberately +// NOT on the denylist — see the "pagination cursors and CSRF tokens are not +// credentials" case in redact-sensitive.test.ts. Adding it there would either +// blank legitimate cursors everywhere or, if scoped, still leave the next +// plugin's differently-named credential exposed. +// +// So for these routes the set of safely loggable body fields is empty, and we +// log shape instead of content. Top-level key *names* are kept: they are the +// diagnostic that makes the line worth having ("did a `challenge` arrive?") +// and a name is not the credential the sender put in its value. +const UNLOGGABLE_REQUEST_BODY_PATHS = [ + // Both forms are matched on purpose. `httpLogger` is installed app-wide but + // Express rewrites `req.url` to the mount-relative path while a mounted + // router is handling the request, and pino-http reads it at response time — + // so this route is logged as `/plugins/...`, not `/api/plugins/...`. Field + // evidence: the WARN lines reported on BLO-29716 carry the unprefixed form. + // Matching both keeps the guard correct if that mount detail ever changes. + /^(?:\/api)?\/plugins\/[^/]+\/webhooks\/[^/]+(?:\/|$)/, +]; + +export function shouldOmitRequestBodyFromLog(url: string | undefined): boolean { + if (!url) return false; + const pathname = normalizePath(url); + return UNLOGGABLE_REQUEST_BODY_PATHS.some((pattern) => pattern.test(pathname)); +} + +const MAX_SUMMARIZED_KEYS = 40; + +// A bounded stand-in for an omitted body: enough to debug a rejection +// (how big was it, what shape was it) with no sender-supplied value in it. +export function summarizeOmittedRequestBody(body: unknown): Record { + const summary: Record = { reqBody: "[OMITTED: untrusted webhook payload]" }; + + let bytes: number | undefined; + try { + const serialized = typeof body === "string" ? body : JSON.stringify(body); + if (typeof serialized === "string") bytes = Buffer.byteLength(serialized, "utf8"); + } catch { + // Cyclic or otherwise unserializable — report the shape we can see. + } + if (bytes !== undefined) summary.reqBodyBytes = bytes; + + if (body && typeof body === "object" && !Array.isArray(body)) { + const keys = Object.keys(body as Record).sort(); + summary.reqBodyKeys = keys.slice(0, MAX_SUMMARIZED_KEYS); + if (keys.length > MAX_SUMMARIZED_KEYS) { + summary.reqBodyKeysTruncated = keys.length - MAX_SUMMARIZED_KEYS; + } + } else if (Array.isArray(body)) { + summary.reqBodyArrayLength = body.length; + } + + return summary; +} + +type LoggedRequest = { + url?: string; + originalUrl?: string; + body?: unknown; + params?: unknown; + query?: unknown; + route?: { path?: string }; +}; + +type LoggedResponse = { + statusCode: number; + __errorContext?: { error?: unknown; reqBody?: unknown; reqParams?: unknown; reqQuery?: unknown }; +}; + +function hasEntries(value: unknown): value is Record { + return Boolean(value) && typeof value === "object" && Object.keys(value as object).length > 0; +} + +// Extracted from logger.ts so both the 4xx and 5xx paths are directly +// testable without importing that module, which opens pino transports and +// creates a log directory at import time. +export function buildHttpLogProps(req: LoggedRequest, res: LoggedResponse): Record { + if (res.statusCode < 400) return {}; + + // Keyed on >= 400, so a readiness guard answering 503 is logged exactly the + // same way a 400 was. That is why BLO-28659's 400 -> 503 change did not fix + // this leak, and why the omission below is keyed on the route, not the code. + const omitBody = shouldOmitRequestBodyFromLog(req.originalUrl ?? req.url); + + const ctx = res.__errorContext; + if (ctx) { + return { + errorContext: ctx.error, + ...(omitBody + ? summarizeOmittedRequestBody(ctx.reqBody) + : { reqBody: redactSensitive(ctx.reqBody) }), + reqParams: redactSensitive(ctx.reqParams), + reqQuery: redactSensitive(ctx.reqQuery), + }; + } + + const props: Record = {}; + if (omitBody) { + Object.assign(props, summarizeOmittedRequestBody(req.body)); + } else if (hasEntries(req.body)) { + props.reqBody = redactSensitive(req.body); + } + if (hasEntries(req.params)) props.reqParams = redactSensitive(req.params); + if (hasEntries(req.query)) props.reqQuery = redactSensitive(req.query); + if (req.route?.path) props.routePath = req.route.path; + return props; +} diff --git a/server/src/middleware/logger.ts b/server/src/middleware/logger.ts index e014a34ca60a..68b071028df6 100644 --- a/server/src/middleware/logger.ts +++ b/server/src/middleware/logger.ts @@ -4,8 +4,7 @@ import pino from "pino"; import { pinoHttp } from "pino-http"; import { readConfigFile } from "../config-file.js"; import { resolveDefaultLogsDir, resolveHomeAwarePath } from "../home-paths.js"; -import { shouldSilenceHttpSuccessLog } from "./http-log-policy.js"; -import { redactSensitive } from "./redact-sensitive.js"; +import { buildHttpLogProps, shouldSilenceHttpSuccessLog } from "./http-log-policy.js"; function resolveServerLogDir(): string { const envOverride = process.env.PAPERCLIP_LOG_DIR?.trim(); @@ -65,32 +64,6 @@ export const httpLogger = pinoHttp({ return `${req.method} ${req.url} ${res.statusCode} — ${errMsg}`; }, customProps(req, res) { - if (res.statusCode >= 400) { - const ctx = (res as any).__errorContext; - if (ctx) { - return { - errorContext: ctx.error, - reqBody: redactSensitive(ctx.reqBody), - reqParams: redactSensitive(ctx.reqParams), - reqQuery: redactSensitive(ctx.reqQuery), - }; - } - const props: Record = {}; - const { body, params, query } = req as any; - if (body && typeof body === "object" && Object.keys(body).length > 0) { - props.reqBody = redactSensitive(body); - } - if (params && typeof params === "object" && Object.keys(params).length > 0) { - props.reqParams = redactSensitive(params); - } - if (query && typeof query === "object" && Object.keys(query).length > 0) { - props.reqQuery = redactSensitive(query); - } - if ((req as any).route?.path) { - props.routePath = (req as any).route.path; - } - return props; - } - return {}; + return buildHttpLogProps(req as never, res as never); }, }); From 4dc1da700e2ae95c545af75fa4f38e4978a05590 Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Mon, 14 Sep 2026 03:30:48 +0000 Subject: [PATCH 2/2] fix(logging): drop the webhook query string from rejection logs too (BLO-29716) Review follow-up on #1700. The body omission left the identical channel open one field over: senders put data in the query string on these URLs (the route reads `req.query.companyId`) and bare `token` is not on the redaction denylist, so `.../webhooks/slack-events?token=Y` wrote Y to the same WARN line the body fix had just cleaned. - buildHttpLogProps: when the route's sender input is unloggable, replace `reqQuery` with the same bounded summary the body gets (placeholder + sorted key names), on both the direct and the error-handler branch. `reqParams` stays: pluginId/endpointKey come from the route path. - The URL reaches the line twice more: the message (`req.url`, the mount-relative form pino-http reads at finish) and pino-http's own serialized `req` (`url` = originalUrl, `query` = parsed), which the file target does not `ignore`. Both drop the query string on these routes. - Bound each summarized key name to 64 chars as well as the count; key names on these routes are sender-authored. - Move the pino-http wiring into `createHttpLogger(logger)` in http-log-policy.ts and export LoggedRequest/LoggedResponse, so the production `customProps` call site is `buildHttpLogProps(req, res)` with no cast (both types are structurally assignable from IncomingMessage/ServerResponse), and so a test can drive the real wiring over a real Express request with an in-memory pino. That test asserts neither sentinel appears anywhere in the emitted line for 400 and 503, and that a non-webhook route still logs its query and redacted body. Co-Authored-By: Claude Fable 5.1 Signed-off-by: Omar Ramadan --- server/src/__tests__/http-log-policy.test.ts | 154 +++++++++++++++++-- server/src/middleware/http-log-policy.ts | 110 +++++++++++-- server/src/middleware/logger.ts | 26 +--- 3 files changed, 240 insertions(+), 50 deletions(-) diff --git a/server/src/__tests__/http-log-policy.test.ts b/server/src/__tests__/http-log-policy.test.ts index 7c9bea8a2c03..d8e5345ff5f4 100644 --- a/server/src/__tests__/http-log-policy.test.ts +++ b/server/src/__tests__/http-log-policy.test.ts @@ -1,5 +1,14 @@ -import { describe, expect, it } from "vitest"; -import { buildHttpLogProps, shouldOmitRequestBodyFromLog, shouldSilenceHttpSuccessLog } from "../middleware/http-log-policy.js"; +import { Writable } from "node:stream"; +import express from "express"; +import pino from "pino"; +import request from "supertest"; +import { describe, expect, it, vi } from "vitest"; +import { + buildHttpLogProps, + createHttpLogger, + shouldOmitRequestBodyFromLog, + shouldSilenceHttpSuccessLog, +} from "../middleware/http-log-policy.js"; describe("shouldSilenceHttpSuccessLog", () => { it("silences cached 304 responses", () => { @@ -100,14 +109,19 @@ describe("shouldOmitRequestBodyFromLog", () => { }); }); +const SENTINEL = "xoxb-sentinel-verification-token-do-not-log"; +const QUERY_SENTINEL = "qs-sentinel-verification-token-do-not-log"; +const slackBody = { + token: SENTINEL, + type: "event_callback", + team_id: "T123", + event: { type: "message", text: "hi" }, +}; +// This route reads `req.query.companyId`, so senders do put data in the query +// string on these URLs; a `?token=` there is the body leak one field over. +const slackQuery = { companyId: "c1", token: QUERY_SENTINEL }; + describe("buildHttpLogProps — no credential reaches a rejection log line", () => { - const SENTINEL = "xoxb-sentinel-verification-token-do-not-log"; - const slackBody = { - token: SENTINEL, - type: "event_callback", - team_id: "T123", - event: { type: "message", text: "hi" }, - }; // Both statuses are exercised because customProps keys on `>= 400`, not on // 4xx. BLO-28659 moved the readiness guard from 400 to 503; if the guarantee @@ -116,12 +130,14 @@ describe("buildHttpLogProps — no credential reaches a rejection log line", () for (const statusCode of [400, 503]) { it(`omits the Slack verification token on a ${statusCode} rejection`, () => { const props = buildHttpLogProps( - { url: "/plugins/slack/webhooks/slack-events", body: slackBody }, + { url: "/plugins/slack/webhooks/slack-events", body: slackBody, query: slackQuery }, { statusCode }, ); expect(JSON.stringify(props)).not.toContain(SENTINEL); + expect(JSON.stringify(props)).not.toContain(QUERY_SENTINEL); expect(props.reqBody).toBe("[OMITTED: untrusted webhook payload]"); + expect(props.reqQuery).toBe("[OMITTED: untrusted webhook query]"); }); it(`omits it on the ${statusCode} error-handler path as well`, () => { @@ -129,11 +145,16 @@ describe("buildHttpLogProps — no credential reaches a rejection log line", () // a second branch and needs the same guard. const props = buildHttpLogProps( { url: "/plugins/slack/webhooks/slack-events" }, - { statusCode, __errorContext: { error: { message: "boom" }, reqBody: slackBody } }, + { + statusCode, + __errorContext: { error: { message: "boom" }, reqBody: slackBody, reqQuery: slackQuery }, + }, ); expect(JSON.stringify(props)).not.toContain(SENTINEL); + expect(JSON.stringify(props)).not.toContain(QUERY_SENTINEL); expect(props.reqBody).toBe("[OMITTED: untrusted webhook payload]"); + expect(props.reqQuery).toBe("[OMITTED: untrusted webhook query]"); }); } @@ -153,24 +174,129 @@ describe("buildHttpLogProps — no credential reaches a rejection log line", () it("keeps the rejection debuggable — size and shape, never values", () => { const props = buildHttpLogProps( - { url: "/plugins/slack/webhooks/slack-events", body: slackBody }, + { url: "/plugins/slack/webhooks/slack-events", body: slackBody, query: slackQuery, params: { pluginId: "slack" } }, { statusCode: 503 }, ); expect(props.reqBodyKeys).toEqual(["event", "team_id", "token", "type"]); expect(props.reqBodyBytes).toBe(Buffer.byteLength(JSON.stringify(slackBody), "utf8")); + expect(props.reqQueryKeys).toEqual(["companyId", "token"]); + // Route params are ours (pluginId/endpointKey from the path), not the sender's. + expect(props.reqParams).toEqual({ pluginId: "slack" }); + }); + + it("bounds the length of each summarized key, since key names are sender-authored too", () => { + const longKey = "k".repeat(500); + const props = buildHttpLogProps( + { url: "/plugins/acme/webhooks/inbound", body: { [longKey]: 1 }, query: { [longKey]: "v" } }, + { statusCode: 503 }, + ); + + expect(JSON.stringify(props)).not.toContain(longKey); + expect((props.reqBodyKeys as string[])[0]).toHaveLength(65); // 64 chars + ellipsis + expect((props.reqQueryKeys as string[])[0]).toHaveLength(65); }); - it("still logs and redacts bodies on non-webhook routes", () => { + it("still logs and redacts bodies and queries on non-webhook routes", () => { const props = buildHttpLogProps( - { url: "/api/auth/sign-in/email", body: { email: "a@b.co", password: "hunter2" } }, + { + url: "/api/auth/sign-in/email", + body: { email: "a@b.co", password: "hunter2" }, + query: { cursor: "abc", access_token: "t" }, + }, { statusCode: 400 }, ); expect(props.reqBody).toEqual({ email: "a@b.co", password: "[REDACTED]" }); + expect(props.reqQuery).toEqual({ cursor: "abc", access_token: "[REDACTED]" }); }); it("logs nothing extra for a successful response", () => { expect(buildHttpLogProps({ url: "/plugins/slack/webhooks/slack-events", body: slackBody }, { statusCode: 200 })).toEqual({}); }); }); + +// The seam the unit tests above cannot see: does the object pino-http actually +// hands customProps match what buildHttpLogProps expects, and does the whole +// emitted line — message, serialized `req`, custom props — stay clean? Drive +// the real wiring over a real Express request instead of hand-built literals. +describe("httpLogger over a real webhook rejection", () => { + function captureLogger() { + const lines: string[] = []; + const sink = new Writable({ + write(chunk, _encoding, callback) { + lines.push(chunk.toString()); + callback(); + }, + }); + return { logger: pino({ level: "debug" }, sink), lines }; + } + + function buildApp(logger: pino.Logger, statusCode: number) { + const app = express(); + app.use(express.json()); + app.use(createHttpLogger(logger)); + // Mounted the way app.ts mounts the API so req.url is rewritten to the + // mount-relative form at response time, exactly as in production. + const api = express.Router(); + api.post("/plugins/:pluginId/webhooks/:endpointKey", (_req, res) => { + res.status(statusCode).json({ error: "rejected" }); + }); + api.post("/issues", (_req, res) => { + res.status(400).json({ error: "bad" }); + }); + app.use("/api", api); + return app; + } + + async function httpLine(lines: string[]) { + await vi.waitFor(() => { + expect(lines.some((line) => line.includes('"res":'))).toBe(true); + }); + return JSON.parse(lines.find((line) => line.includes('"res":'))!) as Record; + } + + for (const statusCode of [400, 503]) { + it(`emits no sender value anywhere in the ${statusCode} line`, async () => { + const { logger, lines } = captureLogger(); + + await request(buildApp(logger, statusCode)) + .post(`/api/plugins/slack/webhooks/slack-events?companyId=c1&token=${QUERY_SENTINEL}`) + .send(slackBody) + .expect(statusCode); + + const entry = await httpLine(lines); + const emitted = lines.join(""); + expect(emitted).not.toContain(SENTINEL); + expect(emitted).not.toContain(QUERY_SENTINEL); + + expect(entry.reqBody).toBe("[OMITTED: untrusted webhook payload]"); + expect(entry.reqBodyKeys).toEqual(["event", "team_id", "token", "type"]); + expect(entry.reqQuery).toBe("[OMITTED: untrusted webhook query]"); + expect(entry.reqQueryKeys).toEqual(["companyId", "token"]); + expect(entry.reqParams).toEqual({ pluginId: "slack", endpointKey: "slack-events" }); + // The message and pino-http's own serialized `req` carry the URL too; + // both must drop the query string, and the message is the + // mount-relative form the field evidence on BLO-29716 showed. + expect(entry.msg).toMatch(new RegExp(`^POST /plugins/slack/webhooks/slack-events ${statusCode}`)); + expect(entry.req.url).toBe("/api/plugins/slack/webhooks/slack-events"); + expect(entry.req.query).toBe("[OMITTED: untrusted webhook query]"); + }); + } + + it("leaves non-webhook routes logging their query and redacted body", async () => { + const { logger, lines } = captureLogger(); + + await request(buildApp(logger, 503)) + .post("/api/issues?cursor=abc") + .send({ title: "x", password: "hunter2" }) + .expect(400); + + const entry = await httpLine(lines); + // Untouched route: the message keeps its query string as before. + expect(entry.msg).toBe("POST /issues?cursor=abc 400"); + expect(entry.req.url).toBe("/api/issues?cursor=abc"); + expect(entry.reqQuery).toEqual({ cursor: "abc" }); + expect(entry.reqBody).toEqual({ title: "x", password: "[REDACTED]" }); + }); +}); diff --git a/server/src/middleware/http-log-policy.ts b/server/src/middleware/http-log-policy.ts index a05fc3e84192..7ba6c8146291 100644 --- a/server/src/middleware/http-log-policy.ts +++ b/server/src/middleware/http-log-policy.ts @@ -1,3 +1,5 @@ +import type pino from "pino"; +import { pinoHttp } from "pino-http"; import { redactSensitive } from "./redact-sensitive.js"; const SILENCED_SUCCESS_METHODS = new Set(["GET", "HEAD"]); @@ -68,6 +70,13 @@ export function shouldSilenceHttpSuccessLog(method: string | undefined, url: str // log shape instead of content. Top-level key *names* are kept: they are the // diagnostic that makes the line worth having ("did a `challenge` arrive?") // and a name is not the credential the sender put in its value. +// +// The query string is sender-authored on these URLs too — this route reads +// `req.query.companyId`, so senders do put data there, and a `?token=…` is +// one field over from the body with bare `token` equally absent from the +// denylist. So wherever the URL or query reaches a log line (`reqQuery`, the +// message's URL, pino-http's serialized `req`) it is dropped alongside the +// body; `shouldOmitRequestBodyFromLog` governs both. const UNLOGGABLE_REQUEST_BODY_PATHS = [ // Both forms are matched on purpose. `httpLogger` is installed app-wide but // Express rewrites `req.url` to the mount-relative path while a mounted @@ -85,6 +94,21 @@ export function shouldOmitRequestBodyFromLog(url: string | undefined): boolean { } const MAX_SUMMARIZED_KEYS = 40; +// Key names on these routes are sender-authored too, so each one is bounded +// as well as the count; otherwise `{"<64 KiB string>": 1}` lands verbatim. +const MAX_SUMMARIZED_KEY_LENGTH = 64; +const OMITTED_QUERY = "[OMITTED: untrusted webhook query]"; + +function summarizeKeys(field: string, value: Record): Record { + const keys = Object.keys(value).sort(); + const summary: Record = { + [`${field}Keys`]: keys + .slice(0, MAX_SUMMARIZED_KEYS) + .map((k) => (k.length > MAX_SUMMARIZED_KEY_LENGTH ? `${k.slice(0, MAX_SUMMARIZED_KEY_LENGTH)}…` : k)), + }; + if (keys.length > MAX_SUMMARIZED_KEYS) summary[`${field}KeysTruncated`] = keys.length - MAX_SUMMARIZED_KEYS; + return summary; +} // A bounded stand-in for an omitted body: enough to debug a rejection // (how big was it, what shape was it) with no sender-supplied value in it. @@ -101,11 +125,7 @@ export function summarizeOmittedRequestBody(body: unknown): Record).sort(); - summary.reqBodyKeys = keys.slice(0, MAX_SUMMARIZED_KEYS); - if (keys.length > MAX_SUMMARIZED_KEYS) { - summary.reqBodyKeysTruncated = keys.length - MAX_SUMMARIZED_KEYS; - } + Object.assign(summary, summarizeKeys("reqBody", body as Record)); } else if (Array.isArray(body)) { summary.reqBodyArrayLength = body.length; } @@ -113,7 +133,19 @@ export function summarizeOmittedRequestBody(body: unknown): Record { + const summary: Record = { reqQuery: OMITTED_QUERY }; + if (query && typeof query === "object" && !Array.isArray(query)) { + Object.assign(summary, summarizeKeys("reqQuery", query as Record)); + } + return summary; +} + +// Structural subsets of what pino-http hands `customProps` (an +// IncomingMessage/ServerResponse that is Express's Request/Response at +// runtime). Kept assignable from those base types so the production call +// site in createHttpLogger needs no cast and stays type-checked. +export type LoggedRequest = { url?: string; originalUrl?: string; body?: unknown; @@ -122,7 +154,7 @@ type LoggedRequest = { route?: { path?: string }; }; -type LoggedResponse = { +export type LoggedResponse = { statusCode: number; __errorContext?: { error?: unknown; reqBody?: unknown; reqParams?: unknown; reqQuery?: unknown }; }; @@ -140,28 +172,82 @@ export function buildHttpLogProps(req: LoggedRequest, res: LoggedResponse): Reco // Keyed on >= 400, so a readiness guard answering 503 is logged exactly the // same way a 400 was. That is why BLO-28659's 400 -> 503 change did not fix // this leak, and why the omission below is keyed on the route, not the code. - const omitBody = shouldOmitRequestBodyFromLog(req.originalUrl ?? req.url); + const omitSenderInput = shouldOmitRequestBodyFromLog(req.originalUrl ?? req.url); const ctx = res.__errorContext; if (ctx) { return { errorContext: ctx.error, - ...(omitBody + ...(omitSenderInput ? summarizeOmittedRequestBody(ctx.reqBody) : { reqBody: redactSensitive(ctx.reqBody) }), + // reqParams stays: pluginId/endpointKey come from the route path, not + // from the sender. The query string does not, so it goes with the body. reqParams: redactSensitive(ctx.reqParams), - reqQuery: redactSensitive(ctx.reqQuery), + ...(omitSenderInput + ? summarizeOmittedRequestQuery(ctx.reqQuery) + : { reqQuery: redactSensitive(ctx.reqQuery) }), }; } const props: Record = {}; - if (omitBody) { + if (omitSenderInput) { Object.assign(props, summarizeOmittedRequestBody(req.body)); } else if (hasEntries(req.body)) { props.reqBody = redactSensitive(req.body); } if (hasEntries(req.params)) props.reqParams = redactSensitive(req.params); - if (hasEntries(req.query)) props.reqQuery = redactSensitive(req.query); + if (hasEntries(req.query)) { + if (omitSenderInput) Object.assign(props, summarizeOmittedRequestQuery(req.query)); + else props.reqQuery = redactSensitive(req.query); + } if (req.route?.path) props.routePath = req.route.path; return props; } + +// The URL as it may appear in a log line: query string dropped on routes +// whose sender input is unloggable, untouched everywhere else. +function urlForLog(url: string | undefined): string | undefined { + return url !== undefined && shouldOmitRequestBodyFromLog(url) ? normalizePath(url) : url; +} + +// Lives here rather than in logger.ts so a test can drive the real pino-http +// wiring over a real Express request with an in-memory pino, without that +// module opening transports and creating a log directory at import time. +export function createHttpLogger(logger: pino.Logger) { + return pinoHttp({ + logger, + serializers: { + // pino-http wraps this around pino-std-serializers' request serializer, + // so `req` is already the serialized shape: `url` is req.originalUrl — + // query string included — and `query` the parsed form. Both reach the + // file target, which does not `ignore` req the way stdout does. + req(req: { url?: string; query?: unknown }) { + if (req.url && shouldOmitRequestBodyFromLog(req.url)) { + req.url = normalizePath(req.url); + req.query = OMITTED_QUERY; + } + return req; + }, + }, + customLogLevel(req, res, err) { + if (shouldSilenceHttpSuccessLog(req.method, req.url, res.statusCode)) { + return "silent"; + } + if (err || res.statusCode >= 500) return "error"; + if (res.statusCode >= 400) return "warn"; + return "info"; + }, + customSuccessMessage(req, res) { + return `${req.method} ${urlForLog(req.url)} ${res.statusCode}`; + }, + customErrorMessage(req, res, err) { + const ctx = (res as any).__errorContext; + const errMsg = ctx?.error?.message || err?.message || (res as any).err?.message || "unknown error"; + return `${req.method} ${urlForLog(req.url)} ${res.statusCode} — ${errMsg}`; + }, + customProps(req, res) { + return buildHttpLogProps(req, res); + }, + }); +} diff --git a/server/src/middleware/logger.ts b/server/src/middleware/logger.ts index 68b071028df6..b1fc45f440d2 100644 --- a/server/src/middleware/logger.ts +++ b/server/src/middleware/logger.ts @@ -1,10 +1,9 @@ import path from "node:path"; import fs from "node:fs"; import pino from "pino"; -import { pinoHttp } from "pino-http"; import { readConfigFile } from "../config-file.js"; import { resolveDefaultLogsDir, resolveHomeAwarePath } from "../home-paths.js"; -import { buildHttpLogProps, shouldSilenceHttpSuccessLog } from "./http-log-policy.js"; +import { createHttpLogger } from "./http-log-policy.js"; function resolveServerLogDir(): string { const envOverride = process.env.PAPERCLIP_LOG_DIR?.trim(); @@ -45,25 +44,4 @@ export const logger = pino({ ], })); -export const httpLogger = pinoHttp({ - logger, - customLogLevel(_req, res, err) { - if (shouldSilenceHttpSuccessLog(_req.method, _req.url, res.statusCode)) { - return "silent"; - } - if (err || res.statusCode >= 500) return "error"; - if (res.statusCode >= 400) return "warn"; - return "info"; - }, - customSuccessMessage(req, res) { - return `${req.method} ${req.url} ${res.statusCode}`; - }, - customErrorMessage(req, res, err) { - const ctx = (res as any).__errorContext; - const errMsg = ctx?.error?.message || err?.message || (res as any).err?.message || "unknown error"; - return `${req.method} ${req.url} ${res.statusCode} — ${errMsg}`; - }, - customProps(req, res) { - return buildHttpLogProps(req as never, res as never); - }, -}); +export const httpLogger = createHttpLogger(logger);