diff --git a/server/src/__tests__/http-log-policy.test.ts b/server/src/__tests__/http-log-policy.test.ts index 0e540a111614..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 { 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", () => { @@ -71,3 +80,223 @@ 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); + }); +}); + +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", () => { + + // 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, 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`, () => { + // 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, 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]"); + }); + } + + 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, 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 and queries on non-webhook routes", () => { + const props = buildHttpLogProps( + { + 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 a0b93694b229..7ba6c8146291 100644 --- a/server/src/middleware/http-log-policy.ts +++ b/server/src/middleware/http-log-policy.ts @@ -1,3 +1,7 @@ +import type pino from "pino"; +import { pinoHttp } from "pino-http"; +import { redactSensitive } from "./redact-sensitive.js"; + const SILENCED_SUCCESS_METHODS = new Set(["GET", "HEAD"]); const SILENCED_SUCCESS_API_PATHS = [ @@ -48,3 +52,202 @@ 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. +// +// 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 + // 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; +// 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. +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)) { + Object.assign(summary, summarizeKeys("reqBody", body as Record)); + } else if (Array.isArray(body)) { + summary.reqBodyArrayLength = body.length; + } + + return summary; +} + +export function summarizeOmittedRequestQuery(query: 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; + params?: unknown; + query?: unknown; + route?: { path?: string }; +}; + +export 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 omitSenderInput = shouldOmitRequestBodyFromLog(req.originalUrl ?? req.url); + + const ctx = res.__errorContext; + if (ctx) { + return { + errorContext: ctx.error, + ...(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), + ...(omitSenderInput + ? summarizeOmittedRequestQuery(ctx.reqQuery) + : { reqQuery: redactSensitive(ctx.reqQuery) }), + }; + } + + const props: Record = {}; + 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)) { + 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 e014a34ca60a..b1fc45f440d2 100644 --- a/server/src/middleware/logger.ts +++ b/server/src/middleware/logger.ts @@ -1,11 +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 { shouldSilenceHttpSuccessLog } from "./http-log-policy.js"; -import { redactSensitive } from "./redact-sensitive.js"; +import { createHttpLogger } from "./http-log-policy.js"; function resolveServerLogDir(): string { const envOverride = process.env.PAPERCLIP_LOG_DIR?.trim(); @@ -46,51 +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) { - 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 {}; - }, -}); +export const httpLogger = createHttpLogger(logger);