From 3b5a31bbb972530d4b75894a2ef79f688326f717 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Tue, 20 Oct 2026 15:45:36 +0100 Subject: [PATCH 1/9] fix(delete-user-data): log failed kit runs at ERROR severity On 2nd gen, Cloud Run records a function that throws as HTTP 200 and the stack goes to stderr with no severity. Wrap the three triggers so a failure is logged at ERROR with the function name and event id, then rethrown. Document the HTTP 200 behaviour and a log-based alert in the README. --- kits/delete-user-data/CHANGELOG.md | 2 + kits/delete-user-data/README.md | 25 ++++++++ kits/delete-user-data/src/index.ts | 61 +++++++++++++++----- kits/delete-user-data/src/logs.ts | 20 +++++++ kits/delete-user-data/tests/context.test.ts | 22 +++++++ kits/delete-user-data/tests/index.test.ts | 42 +++++++++++++- kits/delete-user-data/tests/logs.test.ts | 64 +++++++++++++++++++++ 7 files changed, 221 insertions(+), 15 deletions(-) create mode 100644 kits/delete-user-data/tests/logs.test.ts diff --git a/kits/delete-user-data/CHANGELOG.md b/kits/delete-user-data/CHANGELOG.md index 0e40c6a6fc..3537811e0d 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 `Function failed on event : ` at ERROR before it fails, so log-based alerts can catch it. See "Failed runs show as HTTP 200" in the README, which also covers timeouts. + - fix: an Eventarc publish failure no longer fails the function. A channel that was deleted or is unreachable answers `PERMISSION_DENIED`, and the publish was awaited after the work, so the deletion completed but the invocation still failed. The publish failure is now logged as a warning and the invocation continues. Deploys also declare `eventarcpublishing.googleapis.com`, so the API is enabled on your project whether or not you use events. The failed invocation used to be redelivered, re-running a deletion that had already succeeded; it no longer is. - fix: `ENABLE_AUTO_DISCOVERY` accepts the extension's `yes` / `no` values again. The kit had declared it as a boolean param, which only counts the literal `true` as enabled, so a `.env` copied from an installed extension instance carried `yes` and silently left auto-discovery switched off. The param is now the extension's labeled `Yes` / `No` select and is read the same way the extension read it. diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index 465d7a7cd0..c62f3ab95c 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -202,6 +202,31 @@ Auth event `google.firebase.auth.user.v2.deleted` instead of the 1st gen This mainly matters if you have infrastructure or alerting keyed to function generation. +### 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 +records these event deliveries as HTTP 200 even when the function fails, so +request status and error-rate charts do not show failures. + +Instead, the kit logs every failed run at ERROR severity, as +`Function failed on event : `, with `functionName` and +`eventId` fields, and then lets the run fail. Error Reporting still groups the +error from the stack trace that follows it, as it did for the extension. To be +told about failures, 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. A timeout shows up only 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. + ### 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 cca4a43d0f..aadd4b4226 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -17,10 +17,13 @@ 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 { assertRequiredParams, CONFIG_EXPRESSIONS, @@ -29,10 +32,12 @@ import { 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"; @@ -109,27 +114,55 @@ function getContext(): HandlerContext { return ctx; } -export const clearData = onUserDeleted((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. - const uid = event.data?.uid; - if (!uid) { - logs.deletionEventMissingUid(event.id); - return; - } - return handleClear(uid, getContext()); -}); +// 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. +function logFailures( + functionName: string, + handler: (event: E) => unknown +): (event: E) => Promise { + return async (event) => { + try { + return await handler(event); + } catch (err) { + logs.unhandledError(functionName, event.id, err); + throw err; + } + }; +} + +export const clearData = onUserDeleted( + logFailures("clearData", (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. + const uid = event.data?.uid; + if (!uid) { + logs.deletionEventMissingUid(event.id); + return; + } + return handleClear(uid, getContext()); + }) +); export const handleSearch = onMessagePublished( { topic: CONFIG_EXPRESSIONS.discoveryTopicName, }, - (event) => runSearch(event.data.message.json, getContext()) + logFailures( + "handleSearch", + (event: CloudEvent>) => + runSearch(event.data.message.json, getContext()) + ) ); export const handleDeletion = onMessagePublished( { topic: CONFIG_EXPRESSIONS.deletionTopicName, }, - (event) => runDeletion(event.data.message.json, getContext()) + logFailures( + "handleDeletion", + (event: CloudEvent>) => + runDeletion(event.data.message.json, getContext()) + ) ); diff --git a/kits/delete-user-data/src/logs.ts b/kits/delete-user-data/src/logs.ts index cbacbc8dd7..2979a4d021 100644 --- a/kits/delete-user-data/src/logs.ts +++ b/kits/delete-user-data/src/logs.ts @@ -126,6 +126,26 @@ export const deletionEventMissingUid = (eventId: string) => { ); }; +// Written without a stack in `message`: the functions framework already prints +// the thrown error's stack to stderr, and Error Reporting groups that entry the +// same way it groups the extension's errors. A stack here would report every +// failure twice, under a second group. +export const unhandledError = ( + functionName: string, + eventId: string, + err: unknown +) => { + logger.write({ + severity: "ERROR", + message: `Function ${functionName} failed on event ${eventId}: ${ + err instanceof Error ? err.message : String(err) + }`, + functionName, + eventId, + errorStack: err instanceof Error ? err.stack : undefined, + }); +}; + 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 59b253b33a..2285cd1894 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,25 @@ 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( + "clearData", + "event-id", + 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 b031ab6387..51e5a2401c 100644 --- a/kits/delete-user-data/tests/index.test.ts +++ b/kits/delete-user-data/tests/index.test.ts @@ -23,7 +23,7 @@ vi.mock("../src/handlers", async (importOriginal) => ({ })); import { handleClear } from "../src/handlers"; -import { clearData } from "../src/index"; +import { clearData, handleDeletion, handleSearch } from "../src/index"; import * as logs from "../src/logs"; function deletionEvent(data: unknown) { @@ -68,3 +68,43 @@ describe("clearData", () => { expect(logs.deletionEventMissingUid).toHaveBeenCalledWith("event-id"); }); }); + +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 () => { + await expect(fn(pubsubEvent("not json"))).rejects.toThrow( + /Unable to parse Pub\/Sub message data as JSON/ + ); + + expect(logs.unhandledError).toHaveBeenCalledWith( + name, + "message-event-id", + expect.any(Error) + ); + }); +}); 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 0000000000..d412d1f843 --- /dev/null +++ b/kits/delete-user-data/tests/logs.test.ts @@ -0,0 +1,64 @@ +/** + * 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 an ERROR entry naming the function, event and error", () => { + const write = vi.spyOn(logger, "write").mockImplementation(() => {}); + const err = new Error("boom"); + + logs.unhandledError("handleDeletion", "event-1", err); + + expect(write).toHaveBeenCalledWith({ + severity: "ERROR", + message: "Function handleDeletion failed on event event-1: boom", + functionName: "handleDeletion", + eventId: "event-1", + errorStack: err.stack, + }); + }); + + // Error Reporting reads stacks from `message`. The framework already logs + // the stack it reports on, so a stack here would report the failure twice. + test("keeps the stack out of the message", () => { + const write = vi.spyOn(logger, "write").mockImplementation(() => {}); + + logs.unhandledError("clearData", "event-2", new Error("boom")); + + expect(write.mock.calls[0][0].message).not.toMatch(/\n\s+at /); + }); + + test("handles a thrown value that is not an Error", () => { + const write = vi.spyOn(logger, "write").mockImplementation(() => {}); + + logs.unhandledError("handleSearch", "event-3", "plain string"); + + expect(write).toHaveBeenCalledWith( + expect.objectContaining({ + severity: "ERROR", + message: "Function handleSearch failed on event event-3: plain string", + errorStack: undefined, + }) + ); + }); +}); From bc30377fb3b429b4dce15f846fba6c6b86cfd227 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Tue, 27 Oct 2026 12:57:21 +0000 Subject: [PATCH 2/9] fix(delete-user-data): log the bare stack at ERROR, like the extension --- kits/delete-user-data/CHANGELOG.md | 2 +- kits/delete-user-data/README.md | 10 +++---- kits/delete-user-data/src/index.ts | 19 +++++------- kits/delete-user-data/src/logs.ts | 21 ++++---------- kits/delete-user-data/tests/context.test.ts | 6 +--- kits/delete-user-data/tests/index.test.ts | 6 +--- kits/delete-user-data/tests/logs.test.ts | 32 ++++++--------------- 7 files changed, 28 insertions(+), 68 deletions(-) diff --git a/kits/delete-user-data/CHANGELOG.md b/kits/delete-user-data/CHANGELOG.md index 3537811e0d..908a266893 100644 --- a/kits/delete-user-data/CHANGELOG.md +++ b/kits/delete-user-data/CHANGELOG.md @@ -1,4 +1,4 @@ -- 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 `Function failed on event : ` at ERROR before it fails, so log-based alerts can catch it. See "Failed runs show as HTTP 200" in the README, which also covers timeouts. +- 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: an Eventarc publish failure no longer fails the function. A channel that was deleted or is unreachable answers `PERMISSION_DENIED`, and the publish was awaited after the work, so the deletion completed but the invocation still failed. The publish failure is now logged as a warning and the invocation continues. Deploys also declare `eventarcpublishing.googleapis.com`, so the API is enabled on your project whether or not you use events. The failed invocation used to be redelivered, re-running a deletion that had already succeeded; it no longer is. diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index c62f3ab95c..08ecea3188 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -209,11 +209,11 @@ On the extension's 1st gen functions, a thrown error or a timeout was logged as records these event deliveries as HTTP 200 even when the function fails, so request status and error-rate charts do not show failures. -Instead, the kit logs every failed run at ERROR severity, as -`Function failed on event : `, with `functionName` and -`eventId` fields, and then lets the run fail. Error Reporting still groups the -error from the stack trace that follows it, as it did for the extension. To be -told about failures, create a +Instead, the kit 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 [log-based alert](https://cloud.google.com/logging/docs/alerting/log-based-alerts) on ERROR severity, for example: diff --git a/kits/delete-user-data/src/index.ts b/kits/delete-user-data/src/index.ts index aadd4b4226..9ab314d1ae 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -118,22 +118,21 @@ function getContext(): HandlerContext { // 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. -function logFailures( - functionName: string, +function logFailures( handler: (event: E) => unknown ): (event: E) => Promise { return async (event) => { try { return await handler(event); } catch (err) { - logs.unhandledError(functionName, event.id, err); + logs.unhandledError(err); throw err; } }; } export const clearData = onUserDeleted( - logFailures("clearData", (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. const uid = event.data?.uid; @@ -149,10 +148,8 @@ export const handleSearch = onMessagePublished( { topic: CONFIG_EXPRESSIONS.discoveryTopicName, }, - logFailures( - "handleSearch", - (event: CloudEvent>) => - runSearch(event.data.message.json, getContext()) + logFailures((event: CloudEvent>) => + runSearch(event.data.message.json, getContext()) ) ); @@ -160,9 +157,7 @@ export const handleDeletion = onMessagePublished( { topic: CONFIG_EXPRESSIONS.deletionTopicName, }, - logFailures( - "handleDeletion", - (event: CloudEvent>) => - runDeletion(event.data.message.json, getContext()) + logFailures((event: CloudEvent>) => + runDeletion(event.data.message.json, getContext()) ) ); diff --git a/kits/delete-user-data/src/logs.ts b/kits/delete-user-data/src/logs.ts index 2979a4d021..14010e4ab5 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,25 +127,13 @@ export const deletionEventMissingUid = (eventId: string) => { ); }; -// Written without a stack in `message`: the functions framework already prints -// the thrown error's stack to stderr, and Error Reporting groups that entry the -// same way it groups the extension's errors. A stack here would report every -// failure twice, under a second group. -export const unhandledError = ( - functionName: string, - eventId: string, - err: unknown -) => { +// 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: `Function ${functionName} failed on event ${eventId}: ${ - err instanceof Error ? err.message : String(err) - }`, - functionName, - eventId, - errorStack: err instanceof Error ? err.stack : undefined, + message: (err instanceof Error && err.stack) || format(err), }); -}; export function warnInvalidPaths(invalidPathCount: number, uid: string) { logger.warn( diff --git a/kits/delete-user-data/tests/context.test.ts b/kits/delete-user-data/tests/context.test.ts index 2285cd1894..ddf87d891a 100644 --- a/kits/delete-user-data/tests/context.test.ts +++ b/kits/delete-user-data/tests/context.test.ts @@ -126,11 +126,7 @@ describe("handler context", () => { await expect(clearData(deletionEvent("uid-7"))).rejects.toBe(err); - expect(logs.unhandledError).toHaveBeenCalledWith( - "clearData", - "event-id", - err - ); + expect(logs.unhandledError).toHaveBeenCalledWith(err); }); test("does not log an error when the deletion succeeds", async () => { diff --git a/kits/delete-user-data/tests/index.test.ts b/kits/delete-user-data/tests/index.test.ts index 51e5a2401c..4f5c092ff6 100644 --- a/kits/delete-user-data/tests/index.test.ts +++ b/kits/delete-user-data/tests/index.test.ts @@ -101,10 +101,6 @@ describe.each([ /Unable to parse Pub\/Sub message data as JSON/ ); - expect(logs.unhandledError).toHaveBeenCalledWith( - name, - "message-event-id", - expect.any(Error) - ); + expect(logs.unhandledError).toHaveBeenCalledWith(expect.any(Error)); }); }); diff --git a/kits/delete-user-data/tests/logs.test.ts b/kits/delete-user-data/tests/logs.test.ts index d412d1f843..270484423d 100644 --- a/kits/delete-user-data/tests/logs.test.ts +++ b/kits/delete-user-data/tests/logs.test.ts @@ -23,42 +23,26 @@ afterEach(() => { }); describe("unhandledError", () => { - test("writes an ERROR entry naming the function, event and error", () => { + test("writes the error's stack as an ERROR entry", () => { const write = vi.spyOn(logger, "write").mockImplementation(() => {}); const err = new Error("boom"); - logs.unhandledError("handleDeletion", "event-1", err); + logs.unhandledError(err); expect(write).toHaveBeenCalledWith({ severity: "ERROR", - message: "Function handleDeletion failed on event event-1: boom", - functionName: "handleDeletion", - eventId: "event-1", - errorStack: err.stack, + message: err.stack, }); }); - // Error Reporting reads stacks from `message`. The framework already logs - // the stack it reports on, so a stack here would report the failure twice. - test("keeps the stack out of the message", () => { - const write = vi.spyOn(logger, "write").mockImplementation(() => {}); - - logs.unhandledError("clearData", "event-2", new Error("boom")); - - expect(write.mock.calls[0][0].message).not.toMatch(/\n\s+at /); - }); - test("handles a thrown value that is not an Error", () => { const write = vi.spyOn(logger, "write").mockImplementation(() => {}); - logs.unhandledError("handleSearch", "event-3", "plain string"); + logs.unhandledError("plain string"); - expect(write).toHaveBeenCalledWith( - expect.objectContaining({ - severity: "ERROR", - message: "Function handleSearch failed on event event-3: plain string", - errorStack: undefined, - }) - ); + expect(write).toHaveBeenCalledWith({ + severity: "ERROR", + message: "plain string", + }); }); }); From 8e38970b679b8a4bc00ee861c0bea12665fb6880 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 2 Nov 2026 18:54:19 +0000 Subject: [PATCH 3/9] fix(delete-user-data): parse Pub/Sub messages with JSON.parse, like the extension message.json wraps a parse error as "Unable to parse Pub/Sub message data as JSON", which Error Reporting groups apart from the extension's plain SyntaxError. --- kits/delete-user-data/src/index.ts | 13 +++++++++++-- kits/delete-user-data/tests/index.test.ts | 7 +++---- 2 files changed, 14 insertions(+), 6 deletions(-) diff --git a/kits/delete-user-data/src/index.ts b/kits/delete-user-data/src/index.ts index 9ab314d1ae..e8e36f7ed8 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -144,12 +144,21 @@ export const clearData = onUserDeleted( }) ); +// Parse the message data the way the extension did. `message.json` wraps a parse +// error as "Unable to parse Pub/Sub message data as JSON", which Error +// Reporting groups apart from the extension's plain SyntaxError. +function parseMessage(event: CloudEvent>): T { + return JSON.parse( + Buffer.from(event.data.message.data, "base64").toString("utf8") + ); +} + export const handleSearch = onMessagePublished( { topic: CONFIG_EXPRESSIONS.discoveryTopicName, }, logFailures((event: CloudEvent>) => - runSearch(event.data.message.json, getContext()) + runSearch(parseMessage(event), getContext()) ) ); @@ -158,6 +167,6 @@ export const handleDeletion = onMessagePublished( topic: CONFIG_EXPRESSIONS.deletionTopicName, }, logFailures((event: CloudEvent>) => - runDeletion(event.data.message.json, getContext()) + runDeletion(parseMessage(event), getContext()) ) ); diff --git a/kits/delete-user-data/tests/index.test.ts b/kits/delete-user-data/tests/index.test.ts index 4f5c092ff6..9dffbf1c91 100644 --- a/kits/delete-user-data/tests/index.test.ts +++ b/kits/delete-user-data/tests/index.test.ts @@ -97,10 +97,9 @@ describe.each([ }); test("logs a malformed message at ERROR severity and rethrows", async () => { - await expect(fn(pubsubEvent("not json"))).rejects.toThrow( - /Unable to parse Pub\/Sub message data as JSON/ - ); + // 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(Error)); + expect(logs.unhandledError).toHaveBeenCalledWith(expect.any(SyntaxError)); }); }); From 5e15db8eebb2d98cbbddf7d97e7a198ce72f8f89 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 2 Nov 2026 18:54:34 +0000 Subject: [PATCH 4/9] docs(delete-user-data): recommend an execution_count alert for failed runs execution_count still reports error, timeout and out of memory on 2nd gen; only Cloud Run's request log and request_count show HTTP 200. --- kits/delete-user-data/README.md | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index 08ecea3188..9dcc630236 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -205,15 +205,22 @@ generation. ### 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 -records these event deliveries as HTTP 200 even when the function fails, so -request status and error-rate charts do not show failures. - -Instead, the kit logs the error's stack trace for every failed run at ERROR +`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 `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 +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: From 872ad7bacfcece072623721ed8e36792cb663f36 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 2 Nov 2026 18:54:41 +0000 Subject: [PATCH 5/9] docs(delete-user-data): describe how out-of-memory crashes are logged --- kits/delete-user-data/README.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index 9dcc630236..99bc4e3b2f 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -234,6 +234,12 @@ A function can't log its own timeout. A timeout shows up only 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. +An out-of-memory crash logs one ERROR per crashed instance (`Memory limit of +256 MiB exceeded…`), which the filter above catches. Each event that was running +on that instance gets only an INFO, HTTP 200 request log that says "The request +failed because…", so the log-based alert fires once per crash, not once per +lost event. + ### Events need an existing channel, and their source has changed The extension created its Eventarc channel when you installed it with events From 3811b0b4b4759afab65729278dda50fa152eb7ab Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 9 Nov 2026 15:39:49 +0000 Subject: [PATCH 6/9] docs(delete-user-data): report out-of-memory runs as crash, with a blank request log --- kits/delete-user-data/README.md | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index 78f8d2f48a..193fb2fea0 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -258,8 +258,8 @@ On the extension's 1st gen functions, a thrown error or a timeout was logged as 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 `out of memory`, as it did for -the extension. +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 @@ -284,10 +284,8 @@ log that says "The request has been terminated because it has reached the maximum request timeout", which the second clause above matches. An out-of-memory crash logs one ERROR per crashed instance (`Memory limit of -256 MiB exceeded…`), which the filter above catches. Each event that was running -on that instance gets only an INFO, HTTP 200 request log that says "The request -failed because…", so the log-based alert fires once per crash, not once per -lost event. +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 From e22e191b569fbf1db972ec893da8bda6d5a44644 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 9 Nov 2026 15:39:49 +0000 Subject: [PATCH 7/9] fix(delete-user-data): don't log an ERROR when a run fails after its timeout --- kits/delete-user-data/README.md | 9 ++-- kits/delete-user-data/src/index.ts | 38 +++++++++++--- kits/delete-user-data/tests/index.test.ts | 63 +++++++++++++++++++++++ 3 files changed, 100 insertions(+), 10 deletions(-) diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index 193fb2fea0..d74483cc0a 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -279,9 +279,12 @@ resource.labels.service_name=~"^kit--" (severity>=ERROR OR textPayload:"maximum request timeout") ``` -A function can't log its own timeout. A timeout shows up only 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. +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 doesn't log the error, since the timeout was already logged. 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 diff --git a/kits/delete-user-data/src/index.ts b/kits/delete-user-data/src/index.ts index d7725b0d8b..2f79df59ea 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -110,18 +110,47 @@ 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 logged nothing after a timeout, so neither does the kit: Cloud Run +// has already logged the timeout, and an ERROR now would alert a second time. function logFailures( handler: (event: E) => unknown ): (event: E) => Promise { return async (event) => { + const started = Date.now(); try { return await handler(event); } catch (err) { - logs.unhandledError(err); + if (Date.now() - started < timeoutMs()) { + logs.unhandledError(err); + } throw err; } }; @@ -142,12 +171,7 @@ function logFailures( * 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, diff --git a/kits/delete-user-data/tests/index.test.ts b/kits/delete-user-data/tests/index.test.ts index 92c1b6b5eb..855a18dd44 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"; @@ -103,6 +104,68 @@ describe.each([ expect(logs.unhandledError).toHaveBeenCalledWith(expect.any(SyntaxError)); }); + + // A timed-out run keeps going on 2nd gen. The extension logged nothing after + // the timeout, and Cloud Run has already logged it. + test.each([ + [59_999, 1], + [60_000, 0], + ])( + "after %ims at the default timeout, logs the error %i times and rethrows", + async (elapsed, calls) => { + vi.spyOn(Date, "now").mockReturnValueOnce(0).mockReturnValueOnce(elapsed); + + await expect(fn(pubsubEvent("not json"))).rejects.toThrow(SyntaxError); + + expect(logs.unhandledError).toHaveBeenCalledTimes(calls); + } + ); +}); + +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"); + }, + ], + ])( + "logs 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"); + + for (const [elapsed, calls] of [ + [299_999, 1], + [300_000, 1], + ]) { + vi.spyOn(Date, "now") + .mockReturnValueOnce(0) + .mockReturnValueOnce(elapsed); + await expect(kit.handleSearch(pubsubEvent("not json"))).rejects.toThrow( + SyntaxError + ); + expect(kitLogs.unhandledError).toHaveBeenCalledTimes(calls); + } + } + ); }); describe("module load", () => { From 00b707e374cca3f37b04329680820ad3b0c00597 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 9 Nov 2026 15:39:49 +0000 Subject: [PATCH 8/9] docs(delete-user-data): don't claim the plain SyntaxError groups with the extension's --- kits/delete-user-data/src/index.ts | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/kits/delete-user-data/src/index.ts b/kits/delete-user-data/src/index.ts index 2f79df59ea..941bb37f9e 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -195,9 +195,10 @@ export const clearData = onUserDeleted( }) ); -// Parse the message data the way the extension did. `message.json` wraps a parse -// error as "Unable to parse Pub/Sub message data as JSON", which Error -// Reporting groups apart from the extension's plain SyntaxError. +// 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") From 30b9306ffaa512a0746bea2415cd38271d0baebd Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Mon, 9 Nov 2026 16:43:14 +0000 Subject: [PATCH 9/9] fix(delete-user-data): drop an error thrown after the timeout instead of rethrowing it --- kits/delete-user-data/README.md | 3 +- kits/delete-user-data/src/index.ts | 10 +++-- kits/delete-user-data/tests/index.test.ts | 48 +++++++++++------------ 3 files changed, 32 insertions(+), 29 deletions(-) diff --git a/kits/delete-user-data/README.md b/kits/delete-user-data/README.md index d74483cc0a..4adb439e40 100644 --- a/kits/delete-user-data/README.md +++ b/kits/delete-user-data/README.md @@ -284,7 +284,8 @@ 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 doesn't log the error, since the timeout was already logged. +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 diff --git a/kits/delete-user-data/src/index.ts b/kits/delete-user-data/src/index.ts index 941bb37f9e..fb64c0c46f 100644 --- a/kits/delete-user-data/src/index.ts +++ b/kits/delete-user-data/src/index.ts @@ -138,8 +138,9 @@ function timeoutMs(): number { // 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 logged nothing after a timeout, so neither does the kit: Cloud Run -// has already logged the timeout, and an ERROR now would alert a second time. +// 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 { @@ -148,9 +149,10 @@ function logFailures( try { return await handler(event); } catch (err) { - if (Date.now() - started < timeoutMs()) { - logs.unhandledError(err); + if (Date.now() - started >= timeoutMs()) { + return; } + logs.unhandledError(err); throw err; } }; diff --git a/kits/delete-user-data/tests/index.test.ts b/kits/delete-user-data/tests/index.test.ts index 855a18dd44..8361b8947e 100644 --- a/kits/delete-user-data/tests/index.test.ts +++ b/kits/delete-user-data/tests/index.test.ts @@ -105,21 +105,24 @@ describe.each([ expect(logs.unhandledError).toHaveBeenCalledWith(expect.any(SyntaxError)); }); - // A timed-out run keeps going on 2nd gen. The extension logged nothing after - // the timeout, and Cloud Run has already logged it. - test.each([ - [59_999, 1], - [60_000, 0], - ])( - "after %ims at the default timeout, logs the error %i times and rethrows", - async (elapsed, calls) => { - vi.spyOn(Date, "now").mockReturnValueOnce(0).mockReturnValueOnce(elapsed); + // 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); + await expect(fn(pubsubEvent("not json"))).rejects.toThrow(SyntaxError); - expect(logs.unhandledError).toHaveBeenCalledTimes(calls); - } - ); + 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", () => { @@ -145,25 +148,22 @@ describe("with a global timeout", () => { }, ], ])( - "logs errors until the global timeout, set as %s", + "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"); - - for (const [elapsed, calls] of [ - [299_999, 1], - [300_000, 1], - ]) { + const run = (elapsed: number) => { vi.spyOn(Date, "now") .mockReturnValueOnce(0) .mockReturnValueOnce(elapsed); - await expect(kit.handleSearch(pubsubEvent("not json"))).rejects.toThrow( - SyntaxError - ); - expect(kitLogs.unhandledError).toHaveBeenCalledTimes(calls); - } + 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); } ); });