diff --git a/functions/src/__tests__/create-experiment-log-redaction.test.js b/functions/src/__tests__/create-experiment-log-redaction.test.js new file mode 100644 index 0000000..8d639c7 --- /dev/null +++ b/functions/src/__tests__/create-experiment-log-redaction.test.js @@ -0,0 +1,58 @@ +/** + * @jest-environment node + * + * createExperimentHandler logs a failed createDataContainer to Cloud Logging. + * Auth rides in request headers, but a provider can still echo the token in + * its error text (a Dataverse installation answering "Bad api key "), so + * the logged stack must be scrubbed. The 502 detail still goes back to the + * researcher unchanged: it is their own token, on their own request. + */ + +const TOKEN = "dv-secret-token-1234"; + +jest.mock("../../lib/app.js", () => ({ + db: { doc: () => ({ get: async () => ({ data: () => ({}) }) }) }, +})); +jest.mock("../../lib/connect-provider.js", () => ({ + verifyOwnership: async () => ({ ok: true }), +})); +jest.mock("../../lib/resolve-token.js", () => ({ + __esModule: true, + default: async () => ({ success: true, token: TOKEN, serverUrl: "https://dataverse.mock.test" }), +})); +jest.mock("../../lib/providers/index.js", () => ({ + listProviders: () => ["dataverse"], + getProvider: () => ({ + containerInput: [], + createDataContainer: async () => { + throw new Error(`Dataverse dataset creation failed: 401 Bad api key ${TOKEN}`); + }, + }), +})); + +const { createExperimentHandler } = require("../../lib/create-experiment.js"); + +function mockRes() { + const res = {}; + res.status = jest.fn(() => res); + res.json = jest.fn(() => res); + return res; +} + +it("scrubs the provider token from the logged error", async () => { + const error = jest.spyOn(console, "error").mockImplementation(() => {}); + const res = mockRes(); + + await createExperimentHandler( + { method: "POST", body: { provider: "dataverse", title: "t", uid: "u1", idToken: "x" } }, + res + ); + + expect(res.status).toHaveBeenCalledWith(502); + expect(error).toHaveBeenCalledTimes(1); + const logged = JSON.stringify(error.mock.calls[0]); + expect(logged).not.toContain(TOKEN); + expect(logged).toContain("Bad api key [redacted]"); + expect(logged).toContain("create-experiment"); // the stack survives + error.mockRestore(); +}); diff --git a/functions/src/__tests__/providers-dataverse.test.js b/functions/src/__tests__/providers-dataverse.test.js index 5c9e268..3f6ae89 100644 --- a/functions/src/__tests__/providers-dataverse.test.js +++ b/functions/src/__tests__/providers-dataverse.test.js @@ -9,6 +9,8 @@ // and the docblock + node-fetch mock convention is kept for consistency with // every other adapter suite (see commit 0664bd5/313abbf/9008f67). +import { Readable } from "stream"; + const mockFetch = jest.fn(); jest.mock("node-fetch", () => ({ @@ -30,6 +32,7 @@ function mockResponse({ status, statusText, jsonBody, textBody }) { statusText, json: () => Promise.resolve(jsonBody), text: () => Promise.resolve(textBody), + body: textBody === undefined ? null : Readable.from([Buffer.from(textBody)]), }; } @@ -1372,4 +1375,62 @@ describe("9. validateStaticToken", () => { expect(message).not.toContain("test-token"); warn.mockRestore(); }); + + it("reads only a bounded prefix of a huge body and drops the connection", async () => { + const warn = jest.spyOn(console, "warn").mockImplementation(() => {}); + let pulled = 0; + // An endless 64KB-chunk body: text() would never finish buffering it. + const body = new Readable({ + read() { + pulled += 1; + this.push(Buffer.alloc(64 * 1024, "x")); + }, + }); + mockFetch.mockResolvedValueOnce({ status: 403, statusText: "Forbidden", body }); + + const result = await dataverseProvider.validateStaticToken(auth); + + expect(result).toBe(false); + expect(body.destroyed).toBe(true); + expect(pulled).toBeLessThan(5); + const [message] = warn.mock.calls[0]; + expect(message.length).toBeLessThan(500); + warn.mockRestore(); + }); + + it("gives up on a body that stalls, keeping what arrived", async () => { + jest.useFakeTimers(); + const warn = jest.spyOn(console, "warn").mockImplementation(() => {}); + const body = new Readable({ read() {} }); + body.push("partial block page"); + mockFetch.mockResolvedValueOnce({ status: 503, statusText: "Service Unavailable", body }); + + const pending = dataverseProvider.validateStaticToken(auth); + await jest.advanceTimersByTimeAsync(5000); + const result = await pending; + + expect(result).toBe(false); + expect(body.destroyed).toBe(true); + expect(warn.mock.calls[0][0]).toContain("503: partial block page"); + warn.mockRestore(); + jest.useRealTimers(); + }); + + it("flattens a multi-line body onto one log line", async () => { + const warn = jest.spyOn(console, "warn").mockImplementation(() => {}); + mockFetch.mockResolvedValueOnce( + mockResponse({ + status: 403, + statusText: "Forbidden", + textBody: "\n \n Request blocked\n \n", + }) + ); + + await dataverseProvider.validateStaticToken(auth); + + const [message] = warn.mock.calls[0]; + expect(message).not.toContain("\n"); + expect(message).toContain(" Request blocked "); + warn.mockRestore(); + }); }); diff --git a/functions/src/create-experiment.ts b/functions/src/create-experiment.ts index 781bf92..f2ad68c 100644 --- a/functions/src/create-experiment.ts +++ b/functions/src/create-experiment.ts @@ -25,6 +25,7 @@ import { customAlphabet } from "nanoid"; import { db } from "./app.js"; import { verifyOwnership } from "./connect-provider.js"; import resolveToken from "./resolve-token.js"; +import { redactSecret } from "./redact.js"; import { getProvider, listProviders } from "./providers/index.js"; import { ContainerRef, StorageProviderId, ResolvedAuth } from "./providers/types.js"; import { ExperimentData, UserData } from "./interfaces.js"; @@ -180,10 +181,18 @@ export async function createExperimentHandler(req: Request, res: Response): Prom // Otherwise this failure leaves no server-side trace: the 502 below is // the only record, and it goes to the browser, not Cloud Logging. The // Error itself, not just its message, so the stack and any network - // `code`/`cause` (ECONNRESET, ETIMEDOUT) survive; uid ties it to a - // user's report. Provider errors carry no token -- auth rides in the - // request headers, never the URL or the message. - console.error(`Error creating storage container for provider ${provider}, user ${uid}:`, e); + // `code` (ECONNRESET, ETIMEDOUT) survive; uid ties it to a user's + // report. Auth rides in request headers, never the URL, but a provider + // can still echo the token in its error text (a Dataverse installation + // answering "Bad api key "), so the stack is scrubbed before it + // reaches Cloud Logging. + const trace = e instanceof Error ? (e.stack ?? e.message) : String(e); + const code = (e as { code?: unknown } | null)?.code; + console.error( + `Error creating storage container for provider ${provider}, user ${uid}:`, + redactSecret(trace, auth.token), + ...(code !== undefined ? [{ code }] : []) + ); res.status(502).json({ error: "Failed to create storage container", detail }); return; } diff --git a/functions/src/providers/dataverse.ts b/functions/src/providers/dataverse.ts index 1e9d2ba..08c68ed 100644 --- a/functions/src/providers/dataverse.ts +++ b/functions/src/providers/dataverse.ts @@ -1,6 +1,8 @@ -import fetch from "node-fetch"; +import fetch, { type Response } from "node-fetch"; +import type { Readable } from "stream"; import { randomBytes } from "crypto"; import { decrypt } from "../crypto-utils.js"; +import { redactSecret } from "../redact.js"; import { UserData } from "../interfaces.js"; import { isAllowedServerUrl } from "./server-url.js"; import { @@ -55,6 +57,39 @@ function quoteHeaderParam(value: string): string { return `"${sanitized}"`; } +// validateStaticToken's server URL is researcher-chosen, so its error body is +// untrusted: read at most this much, for at most this long, then drop the +// connection. response.text() would buffer a hostile multi-hundred-MB (or +// slow-drip) body into dashboardapi's shared memory. The margin over the 300 +// characters logged leaves room for a token-sized redaction. +const VALIDATE_BODY_MAX_BYTES = 4096; +const VALIDATE_BODY_TIMEOUT_MS = 5000; + +// Never throws: the body is diagnostic only, and an unreadable one still +// leaves the status. +async function readBodyPrefix(response: Response, maxBytes: number, timeoutMs: number): Promise { + const stream = response.body as Readable | null; + if (!stream) return ""; + const chunks: Buffer[] = []; + let total = 0; + let timer: NodeJS.Timeout | undefined; + const timedOut = new Promise((resolve) => { + timer = setTimeout(resolve, timeoutMs); + }); + const read = (async () => { + for await (const chunk of stream) { + const buf = Buffer.isBuffer(chunk) ? chunk : Buffer.from(chunk as Uint8Array); + chunks.push(buf); + total += buf.length; + if (total >= maxBytes) break; + } + })().catch(() => {}); + await Promise.race([read, timedOut]); + clearTimeout(timer); + stream.destroy(); + return Buffer.concat(chunks).subarray(0, maxBytes).toString("utf8"); +} + function authHeaders(auth: ResolvedAuth): Record { return { "X-Dataverse-key": auth.token }; } @@ -428,14 +463,11 @@ export const dataverseProvider: StorageProvider = { // Log what the installation actually said. The caller collapses every // non-200 into "Invalid API token", so without this a real 401, a WAF // 403, and an outage 5xx are indistinguishable after the fact. The body - // is truncated (a WAF block page can be large) and scrubbed of the token - // in case an installation echoes the key back in its error message. - let body = ""; - try { - body = (await response.text()).split(auth.token).join("[redacted]").slice(0, 300); - } catch { - // Body is diagnostic only; an unreadable one still leaves the status. - } + // is scrubbed of the token in case an installation echoes the key back in + // its error message, and flattened to one line so a multi-line block page + // stays in one log entry. + const prefix = await readBodyPrefix(response, VALIDATE_BODY_MAX_BYTES, VALIDATE_BODY_TIMEOUT_MS); + const body = redactSecret(prefix, auth.token).replace(/\s+/g, " ").trim().slice(0, 300); console.warn(`dataverse validateStaticToken: ${serverUrl}/api/users/:me returned ${response.status}: ${body}`); return false; }, diff --git a/functions/src/redact.ts b/functions/src/redact.ts new file mode 100644 index 0000000..50a2d28 --- /dev/null +++ b/functions/src/redact.ts @@ -0,0 +1,7 @@ +// Replaces every occurrence of `secret` in `text` before it is logged. An +// empty secret is a no-op: "abc".split("") would otherwise redact between +// every character. +export function redactSecret(text: string, secret: string | undefined): string { + if (!secret) return text; + return text.split(secret).join("[redacted]"); +}