fix(logging): stop plugin webhook rejections logging the inbound body (BLO-29716)

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({});
+  });
+});

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<string, unknown> {
+  const summary: Record<string, unknown> = { 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<string, unknown>).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<string, unknown> {
+  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<string, unknown> {
+  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<string, unknown> = {};
+  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;
+}

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<string, unknown> = {};
-      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);
   },
 });