diff --git a/kits/delete-user-data/CHANGELOG.md b/kits/delete-user-data/CHANGELOG.md index e513ce530..f97972837 100644 --- a/kits/delete-user-data/CHANGELOG.md +++ b/kits/delete-user-data/CHANGELOG.md @@ -1,3 +1,5 @@ +- fix: a failed run is now logged at ERROR severity. On 2nd gen, Cloud Run records a function that throws as HTTP 200, and the stack trace went to stderr with no severity, so failures that the extension reported as `status: 'error'` were easy to miss. Each function now logs the error's stack trace at ERROR before it fails, as the extension did, so log-based alerts can catch it. See "Failed runs show as HTTP 200" in the README, which also covers timeouts. + - fix: `clearData`, `handleSearch` and `handleDeletion` can scale to 3000 instances each again, as the extension's 1st gen functions could. The kit set no `maxInstances`, so each function took the 2nd gen default of 100, and with one event per instance it handled at most 100 deletions or searches at once. `setGlobalOptions({ maxInstances })` still overrides it. Existing kit deployments switch on their next deploy. - fix: the functions deploy to `us-central1` by default again, as the extension did. The kit set no region, so the Firebase CLI deployed them to `us-east1`. The region is now read from `FUNCTION_DEFAULT_REGION` (default `us-central1`), the name `firebase ext:migrate` writes to `.env`, so each instance can deploy to its own region. `setGlobalOptions({ region })` no longer moves the functions; set `FUNCTION_DEFAULT_REGION` instead. diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index 9d2568e62..4adb439e4 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -251,6 +251,46 @@ the `firebase init functions` template sets `maxInstances: 10`, so check your entry file. `setGlobalOptions` can't change concurrency, CPU or ingress, so an ingress setting carried over by `ext:migrate` doesn't apply to the kit. +### Failed runs show as HTTP 200 + +On the extension's 1st gen functions, a thrown error or a timeout was logged as +`finished with status: 'error'` (or `'timeout'`). On 2nd gen, Cloud Run's +request log and its `request_count` metric record these event deliveries as +HTTP 200 even when the function fails. The +`cloudfunctions.googleapis.com/function/execution_count` metric still reports +them with a `status` of `error`, `timeout` or `crash` (out of memory), as it +did for the extension. + +The kit also logs the error's stack trace for every failed run at ERROR +severity, as the extension did, and then lets the run fail. Error Reporting +groups it with the copy of the stack that the functions framework writes to +stderr, so each failure shows up twice in the same group. + +To be told about failures, create a +[metric alert](https://cloud.google.com/monitoring/alerts/using-alerting-ui) +on `execution_count` with `metric.labels.status!="ok"`. It also counts each +event lost to an out-of-memory crash. Alternatively, create a +[log-based alert](https://cloud.google.com/logging/docs/alerting/log-based-alerts) +on ERROR severity, for example: + +``` +resource.type="cloud_run_revision" +resource.labels.service_name=~"^kit--" +(severity>=ERROR OR textPayload:"maximum request timeout") +``` + +A function can't log its own timeout. Cloud Run logs it as an INFO request log +that says "The request has been terminated because it has reached the maximum +request timeout", which the second clause above matches. On 2nd gen, the +timed-out run keeps going in the background, so you may still see its INFO +logs, such as `Successfully removed data for user`, minutes later. If it then +fails, the kit drops the error without logging it, as the extension recorded +nothing after a timeout, so it doesn't reach your alerts or Error Reporting. + +An out-of-memory crash logs one ERROR per crashed instance (`Memory limit of +256 MiB exceeded…`), which the filter above catches. The event that was running +on that instance gets only an INFO, HTTP 200 request log with no message. + ### Events need an existing channel, and their source has changed The extension created its Eventarc channel when you installed it with events diff --git a/kits/delete-user-data/src/index.ts b/kits/delete-user-data/src/index.ts index 97ff3e07d..fb64c0c46 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -17,18 +17,23 @@ import { PubSub } from "@google-cloud/pubsub"; import * as admin from "firebase-admin"; import { getFirestore } from "firebase-admin/firestore"; -import type { Role } from "firebase-functions/v2"; +import type { CloudEvent, Role } from "firebase-functions/v2"; import { requiresAPI, requiresRole } from "firebase-functions/v2"; import { onUserDeleted } from "firebase-functions/v2/identity"; -import { onMessagePublished } from "firebase-functions/v2/pubsub"; +import { + type MessagePublishedData, + onMessagePublished, +} from "firebase-functions/v2/pubsub"; import { assertParams, CONFIG_EXPRESSIONS, configFromEnv } from "./config"; import * as events from "./events"; import { getDatabaseUrl, resolveDeleteUserDataConfig } from "./export-config"; import { + type DeleteMessageData, type HandlerContext, handleClear, handleDeletion as runDeletion, handleSearch as runSearch, + type SearchMessageData, } from "./handlers"; import * as logs from "./logs"; @@ -105,6 +110,54 @@ function getContext(): HandlerContext { return ctx; } +// Read when the functions are defined, as the SDK does. +const globalOptions = ( + globalThis as unknown as Record< + symbol, + { value?: { maxInstances?: unknown; timeoutSeconds?: unknown } } | undefined + > +)[Symbol.for("firebase-functions:v2:globalOptions")]?.value; + +// The kit sets no timeout, so its functions take the global one, or 2nd gen's +// default of 60 seconds for event functions. A global value can be a param. +function timeoutMs(): number { + const option = globalOptions?.timeoutSeconds as + | number + | { value?: () => unknown } + | undefined; + const seconds = + typeof option === "object" && typeof option.value === "function" + ? option.value() + : option; + return (typeof seconds === "number" && seconds > 0 ? seconds : 60) * 1000; +} + +// On 2nd gen, a handler that throws is still recorded as HTTP 200 in the +// request log, and the functions framework prints the stack to stderr with no +// severity. Log the error at ERROR severity so log-based alerts and Error +// Reporting see it, then rethrow so the invocation still counts as failed. +// +// A run that times out keeps going on 2nd gen and can throw minutes later. The +// extension recorded nothing after a timeout, so the kit swallows the error: +// Cloud Run has already logged the timeout and counted the run as one, and a +// rethrow would still put the stack on stderr, where Error Reporting picks it up. +function logFailures( + handler: (event: E) => unknown +): (event: E) => Promise { + return async (event) => { + const started = Date.now(); + try { + return await handler(event); + } catch (err) { + if (Date.now() - started >= timeoutMs()) { + return; + } + logs.unhandledError(err); + throw err; + } + }; +} + /** * The extension's 1st gen functions ran at 0.1666 vCPU, one event per * instance, up to 3000 instances, with internal-only ingress. Without these @@ -120,12 +173,7 @@ function getContext(): HandlerContext { * Concurrency, CPU and ingress are always the extension's, as in the * firestore-bigquery-export kit. */ -const globalMaxInstances = ( - globalThis as unknown as Record< - symbol, - { value?: { maxInstances?: unknown } } | undefined - > -)[Symbol.for("firebase-functions:v2:globalOptions")]?.value?.maxInstances; +const globalMaxInstances = globalOptions?.maxInstances; const EXTENSION_RUNTIME_OPTIONS = { concurrency: 1, @@ -136,7 +184,7 @@ const EXTENSION_RUNTIME_OPTIONS = { export const clearData = onUserDeleted( { ...EXTENSION_RUNTIME_OPTIONS, region: CONFIG_EXPRESSIONS.functionRegion }, - (event) => { + logFailures((event) => { // The Auth event delivers no user record when the payload envelope is // empty, so bail before getContext() rather than initialising the SDKs for // nothing. @@ -146,16 +194,28 @@ export const clearData = onUserDeleted( return; } return handleClear(uid, getContext()); - } + }) ); +// Parse the message data the way the extension did, so a malformed message +// throws the same plain SyntaxError. `message.json` wraps it as "Unable to +// parse Pub/Sub message data as JSON". Error Reporting still groups the two +// apart, since the kit's stack frames are in node_modules. +function parseMessage(event: CloudEvent>): T { + return JSON.parse( + Buffer.from(event.data.message.data, "base64").toString("utf8") + ); +} + export const handleSearch = onMessagePublished( { ...EXTENSION_RUNTIME_OPTIONS, region: CONFIG_EXPRESSIONS.functionRegion, topic: CONFIG_EXPRESSIONS.discoveryTopicName, }, - (event) => runSearch(event.data.message.json, getContext()) + logFailures((event: CloudEvent>) => + runSearch(parseMessage(event), getContext()) + ) ); export const handleDeletion = onMessagePublished( @@ -164,5 +224,7 @@ export const handleDeletion = onMessagePublished( region: CONFIG_EXPRESSIONS.functionRegion, topic: CONFIG_EXPRESSIONS.deletionTopicName, }, - (event) => runDeletion(event.data.message.json, getContext()) + logFailures((event: CloudEvent>) => + runDeletion(parseMessage(event), getContext()) + ) ); diff --git a/kits/delete-user-data/src/logs.ts b/kits/delete-user-data/src/logs.ts index cbacbc8dd..14010e4ab 100644 --- a/kits/delete-user-data/src/logs.ts +++ b/kits/delete-user-data/src/logs.ts @@ -14,6 +14,7 @@ * limitations under the License. */ +import { format } from "node:util"; import { logger } from "firebase-functions"; import type { ResolvedDeleteUserDataConfig } from "./export-config"; @@ -126,6 +127,14 @@ export const deletionEventMissingUid = (eventId: string) => { ); }; +// Logged as the bare stack, like the extension's 1st gen ERROR entry. Error +// Reporting groups it with the framework's own stderr copy of the stack. +export const unhandledError = (err: unknown) => + logger.write({ + severity: "ERROR", + message: (err instanceof Error && err.stack) || format(err), + }); + export function warnInvalidPaths(invalidPathCount: number, uid: string) { logger.warn( `Attempted to delete ${invalidPathCount} invalid paths for deleted user ${uid}` diff --git a/kits/delete-user-data/tests/context.test.ts b/kits/delete-user-data/tests/context.test.ts index 59b253b33..ddf87d891 100644 --- a/kits/delete-user-data/tests/context.test.ts +++ b/kits/delete-user-data/tests/context.test.ts @@ -52,6 +52,7 @@ import * as admin from "firebase-admin"; import type { HandlerContext } from "../src/handlers"; import { handleClear } from "../src/handlers"; import { clearData } from "../src/index"; +import * as logs from "../src/logs"; function deletionEvent(uid: string) { return { @@ -118,4 +119,21 @@ describe("handler context", () => { options: { projectId: PROJECT_ID }, }); }); + + test("logs a failed deletion at ERROR severity and rethrows", async () => { + const err = new Error("boom"); + vi.mocked(handleClear).mockRejectedValueOnce(err); + + await expect(clearData(deletionEvent("uid-7"))).rejects.toBe(err); + + expect(logs.unhandledError).toHaveBeenCalledWith(err); + }); + + test("does not log an error when the deletion succeeds", async () => { + vi.mocked(handleClear).mockResolvedValueOnce(undefined); + + await clearData(deletionEvent("uid-8")); + + expect(logs.unhandledError).not.toHaveBeenCalled(); + }); }); diff --git a/kits/delete-user-data/tests/index.test.ts b/kits/delete-user-data/tests/index.test.ts index eb4ca82ae..8361b8947 100644 --- a/kits/delete-user-data/tests/index.test.ts +++ b/kits/delete-user-data/tests/index.test.ts @@ -14,6 +14,7 @@ * limitations under the License. */ +import { defineInt } from "firebase-functions/params"; import { setGlobalOptions } from "firebase-functions/v2"; import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; @@ -70,6 +71,103 @@ describe("clearData", () => { }); }); +function pubsubEvent(data: string) { + return { + specversion: "1.0", + id: "message-event-id", + type: "google.cloud.pubsub.topic.v1.messagePublished", + source: "//pubsub.googleapis.com/projects/test-project/topics/t", + time: "2026-01-01T00:00:00.000Z", + data: { + message: { + messageId: "1", + data: Buffer.from(data).toString("base64"), + }, + subscription: "s", + }, + } as any; +} + +// 2nd gen records a failed invocation as HTTP 200, so the ERROR log is the +// only signal. The rethrow keeps the invocation marked as failed. +describe.each([ + ["handleSearch", handleSearch], + ["handleDeletion", handleDeletion], +] as const)("%s", (name, fn) => { + beforeEach(() => { + vi.clearAllMocks(); + }); + + test("logs a malformed message at ERROR severity and rethrows", async () => { + // The plain SyntaxError, as the extension threw, not `message.json`'s wrapper. + await expect(fn(pubsubEvent("not json"))).rejects.toThrow(SyntaxError); + + expect(logs.unhandledError).toHaveBeenCalledWith(expect.any(SyntaxError)); + }); + + // A timed-out run keeps going on 2nd gen. The extension recorded nothing + // after the timeout, and Cloud Run has already logged it, so a late error is + // neither logged nor rethrown to the framework's stderr. + test("logs and rethrows an error just before the default timeout", async () => { + vi.spyOn(Date, "now").mockReturnValueOnce(0).mockReturnValueOnce(59_999); + + await expect(fn(pubsubEvent("not json"))).rejects.toThrow(SyntaxError); + + expect(logs.unhandledError).toHaveBeenCalledTimes(1); + }); + + test("drops an error at the default timeout", async () => { + vi.spyOn(Date, "now").mockReturnValueOnce(0).mockReturnValueOnce(60_000); + + await expect(fn(pubsubEvent("not json"))).resolves.toBeUndefined(); + + expect(logs.unhandledError).not.toHaveBeenCalled(); + }); +}); + +describe("with a global timeout", () => { + beforeEach(() => { + vi.clearAllMocks(); + }); + + afterEach(() => { + delete (globalThis as any)[ + Symbol.for("firebase-functions:v2:globalOptions") + ].value; + vi.unstubAllEnvs(); + vi.restoreAllMocks(); + }); + + test.each([ + ["a number", () => 300], + [ + "a param", + () => { + vi.stubEnv("KIT_TEST_TIMEOUT_SECONDS", "300"); + return defineInt("KIT_TEST_TIMEOUT_SECONDS"); + }, + ], + ])( + "reports errors until the global timeout, set as %s", + async (_name, timeout) => { + setGlobalOptions({ timeoutSeconds: timeout() }); + vi.resetModules(); + const kit = await import("../src/index"); + const kitLogs = await import("../src/logs"); + const run = (elapsed: number) => { + vi.spyOn(Date, "now") + .mockReturnValueOnce(0) + .mockReturnValueOnce(elapsed); + return kit.handleSearch(pubsubEvent("not json")); + }; + + await expect(run(299_999)).rejects.toThrow(SyntaxError); + await expect(run(300_000)).resolves.toBeUndefined(); + expect(kitLogs.unhandledError).toHaveBeenCalledTimes(1); + } + ); +}); + describe("module load", () => { afterEach(() => { vi.unstubAllEnvs(); diff --git a/kits/delete-user-data/tests/logs.test.ts b/kits/delete-user-data/tests/logs.test.ts new file mode 100644 index 000000000..270484423 --- /dev/null +++ b/kits/delete-user-data/tests/logs.test.ts @@ -0,0 +1,48 @@ +/** + * Copyright 2026 Google LLC + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import { logger } from "firebase-functions"; +import { afterEach, describe, expect, test, vi } from "vitest"; +import * as logs from "../src/logs"; + +afterEach(() => { + vi.restoreAllMocks(); +}); + +describe("unhandledError", () => { + test("writes the error's stack as an ERROR entry", () => { + const write = vi.spyOn(logger, "write").mockImplementation(() => {}); + const err = new Error("boom"); + + logs.unhandledError(err); + + expect(write).toHaveBeenCalledWith({ + severity: "ERROR", + message: err.stack, + }); + }); + + test("handles a thrown value that is not an Error", () => { + const write = vi.spyOn(logger, "write").mockImplementation(() => {}); + + logs.unhandledError("plain string"); + + expect(write).toHaveBeenCalledWith({ + severity: "ERROR", + message: "plain string", + }); + }); +});