fix(delete-user-data): log failed kit runs at ERROR severity

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.

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-<instance id>-"
+(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

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<E>(
+  handler: (event: E) => unknown
+): (event: E) => Promise<unknown> {
+  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<T>(event: CloudEvent<MessagePublishedData<T>>): 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<MessagePublishedData<SearchMessageData>>) =>
+    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<MessagePublishedData<DeleteMessageData>>) =>
+    runDeletion(parseMessage(event), getContext())
+  )
 );

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}`

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

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();