From 3b5a31bbb972530d4b75894a2ef79f688326f717 Mon Sep 17 00:00:00 2001 From: Corie Watson Date: Tue, 20 Oct 2026 15:45:36 +0100 Subject: [PATCH 1/2] 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/2] 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", + }); }); });