Repository navigation
Conversation
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.
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
This pull request introduces explicit error logging at ERROR severity for failed function runs in the delete-user-data kit, addressing an issue where 2nd gen Cloud Run functions record failures as HTTP 200. It adds a logFailures wrapper to catch, log, and rethrow errors, along with corresponding tests and documentation. The feedback suggests improving the robustness of logFailures by using optional chaining to prevent secondary crashes when accessing event.id on potentially null or undefined events, and enhancing unhandledError to support plain objects that contain message or stack properties instead of only checking for instances of the standard Error class.
| 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 <name> failed on event <id>: <error>`, 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: |
There was a problem hiding this comment.
Problem: Error-rate metrics do show failures. The cloudfunctions.googleapis.com/function/execution_count metric reports error, timeout and out of memory for the kit, as it does for the extension; only Cloud Run's request log and request_count show 200. Say that, and recommend a metric alert on execution_count with metric.labels.status!="ok" first (it also counts each event lost to an out-of-memory crash), with the log filter as a second option.
| logFailures( | ||
| "handleSearch", | ||
| (event: CloudEvent<MessagePublishedData<SearchMessageData>>) => | ||
| runSearch(event.data.message.json, getContext()) |
There was a problem hiding this comment.
Problem: A malformed Pub/Sub message fails with a different error. message.json wraps the parse error as Error: Unable to parse Pub/Sub message data as JSON: …; the extension throws the plain SyntaxError: Unexpected token …, and Error Reporting groups them differently. Use JSON.parse(Buffer.from(event.data.message.data, "base64").toString("utf8")) here and at 166, and update tests/index.test.ts:100-102.
| 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 |
There was a problem hiding this comment.
Nit: Out-of-memory crashes aren't covered. A crash logs one ERROR per crashed instance (Memory limit of 256 MiB exceeded…), then each event that was running on it gets only an INFO, HTTP 200 "The request failed because…" line. Mention it; the filter already catches the ERROR line.
| `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 |
There was a problem hiding this comment.
Nit: Error Reporting doesn't group "as it did for the extension". The kit's code runs from node_modules, so different errors can merge into one group where the extension kept them apart. Drop the claim and record the difference in #3249.
| 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 /); | ||
| }); |
There was a problem hiding this comment.
Nit: The tests lock in the invented text. With the fix, assert { severity: "ERROR", message: err.stack } (and format(value) for a non-Error) and drop "keeps the stack out of the message". Keep the rethrow tests: they protect the execution_count status.
Logs every failed kit run at ERROR severity, so failures are visible even though 2nd gen records them as HTTP 200. Fixes #3251 (part of #3249).
Changes
clearData,handleSearchandhandleDeletionare wrapped so any thrown error is logged, then rethrown so the run still fails. The newlogs.unhandledErrorwrites one ERROR entry:Function <name> failed on event <id>: <error message>, withfunctionName,eventIdanderrorStackfields.messageon purpose. The functions framework already prints the stack to stderr, and Error Reporting groups that entry in the same group as the extension's error. A first version usedlogger.error(msg, err): Error Reporting then opened a second group for every failure (checked in deployment), so it was dropped.tests/logs.test.ts(new), plus failure cases intests/index.test.ts(malformed Pub/Sub message on both Pub/Sub triggers) andtests/context.test.ts(clearDatarejects / succeeds).finished with status: 'timeout'at DEBUG, and thestatus: 'error'line is DEBUG too, with the error itself at ERROR. It now also says that Error Reporting already picked up the kit's stderr stack.Testing
Deployed on a test project: the extension
firebase/delete-user-data@0.1.30, the kit fromkitsand the fixed kit. Each had two instances: one withSEARCH_FUNCTIONpointing at an HTTPS function that answers200with the bodynot json, and one withSELECTED_DATABASE_INSTANCE=<nonexistent>andRTDB_PATHSset. I publishednot jsonto each deletion and discovery topic, then created and deleted a test user.handleDeletion,handleSearch)status: 'error'(DEBUG)Function handleDeletion failed on event …: Unable to parse Pub/Sub message data as JSON…at ERROR, then the same stderr stackSEARCH_FUNCTIONreturns non-JSON (clearData)status: 'error'(DEBUG)Function clearData failed on event …: Unexpected token 'o'…at ERROR, then the stderr stackclearData)status: 'timeout'(DEBUG) onlyLogEntry.errorGroups)The README's alert filter (
severity>=ERROR OR textPayload:"maximum request timeout"on the instance's services) matched all three fixed-kit failures and the timeout in both kits. Before the fix, it matched only the timeout.Unit tests:
vitest runpasses (16 files, 126 tests). Prettier passes on the changed files.tscpasses, but only with a temporarily available@types/node: onkits,pnpm buildfails withTS2688: Cannot find type definition file for 'node'because@types/nodeisn't installed, which this change doesn't cause. (pnpm testitself tries to reinstall first because the lockfile is stale onkits, so I ran vitest directly.)