Skip to content

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

Open
CorieW wants to merge 11 commits into
kitsfrom
fix/kits-delete-user-data-error-logging
Open

CorieW wants to merge 11 commits into
kitsfrom
fix/kits-delete-user-data-error-logging

Conversation

@CorieW

@CorieW CorieW commented Oct 20, 2026 •

Copy link
Copy Markdown
Member

Logs every failed kit run at ERROR severity, as the extension did. On 2nd gen a failed run is still logged as HTTP 200, so before this a failure was only a stderr stack with no severity, and ERROR alerts never fired. Fixes #3251 (part of #3249).

Changes

  • clearData, handleSearch and handleDeletion log a thrown error with logs.unhandledError (one ERROR entry with the bare stack, as the extension did), then rethrow it so the run still fails.
  • If a run fails after its timeout (the global timeoutSeconds, default 60s), the error is dropped, neither logged nor rethrown, since the extension recorded nothing after a timeout and Cloud Run has already logged and counted it.
  • Pub/Sub data is parsed with JSON.parse(Buffer.from(data, "base64").toString("utf8")), so a malformed message throws the extension's plain SyntaxError instead of firebase-functions' wrapper.
  • README: new "Failed runs show as HTTP 200" section recommending a metric alert on cloudfunctions.googleapis.com/function/execution_count with status!="ok", or a log-based alert. CHANGELOG updated.
  • Tests for the logging, malformed messages, timeouts (default, number and param) and clearData.
  • Corrected the issue: the extension logs a timeout at DEBUG, not ERROR.

Testing

On a test project, I deployed firebase/delete-user-data@0.1.30 and the kit from this branch with the same config: a missing Firestore database, and a SEARCH_FUNCTION helper that returns not json, sleeps 75s, or returns a 400 MB body. A second kit instance had a 120s global timeout param. I published malformed and valid messages, deleted test users, and checked logs, Error Reporting and execution_count. "Kit before" is the kit on kits; rows this PR doesn't change come from the code.

Case Extension Kit before Kit after
Malformed message (handleSearch, handleDeletion) ERROR with the bare SyntaxError stack; status: 'error' (DEBUG) stderr stack with no severity, for firebase-functions' "Unable to parse Pub/Sub message data as JSON" wrapper; request log INFO 200 ERROR with the same bare SyntaxError stack as the extension, plus the framework's stderr copy; request log INFO 200
Missing Firestore database (Error: 5 NOT_FOUND) ERROR with the first part of the stack; 1st gen splits the rest into ~20 entries with no severity stderr stack with no severity ERROR with the full stack, plus the stderr copy
SEARCH_FUNCTION returns not json (clearData) ERROR with the stack stderr stack with no severity ERROR with the same stack, plus the stderr copy
Timeout (60s) status: 'timeout' (DEBUG) only INFO 200 request log, "…terminated because it has reached the maximum request timeout" same as before
Run that fails after the timeout nothing stderr stack with no severity, which reaches Error Reporting nothing (no ERROR, no stderr stack, no Error Reporting entry)
Run that succeeds after the timeout nothing INFO Successfully removed data for user once it finishes same as before
Same failure at 75s with a 120s global timeout — stderr stack with no severity ERROR, plus the stderr copy
Out of memory ERROR Memory limit of 256 MiB exceeded…; status: 'crash' (DEBUG) ERROR with the same message from the platform; request log INFO 200 with no message same as before
Extension Kit before Kit after
execution_count statuses error, timeout, crash the same (the platform reports them; this PR doesn't change it) the same counts as the extension for every function and status
Error Reporting each failure once, in its group each failure once, from the stderr stack; the malformed message in its own group (the wrapper's message) each failure twice in its group (the ERROR entry and the stderr copy, as the README says); the same groups as the extension, except the malformed-message SyntaxError, whose top frame is the kit's code in node_modules
README log filter (severity>=ERROR OR textPayload:"maximum request timeout") — matches only timeouts and out-of-memory crashes matches exactly one entry per failure (12 of 12), and nothing for a run that failed after its timeout

An earlier version that only skipped logging after a timeout still let the framework's stderr stack reach Error Reporting; dropping the error fixed that.

vitest run passes (179 tests) and Prettier passes. tsc passes with @types/node temporarily installed; without it pnpm build fails on kits, which this change doesn't cause.

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 gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment thread kits/delete-user-data/src/index.ts Resolved
Comment thread kits/delete-user-data/src/logs.ts Resolved
Comment thread kits/delete-user-data/src/logs.ts Resolved
Comment thread kits/delete-user-data/README.md Resolved
Comment thread kits/delete-user-data/src/index.ts Resolved
Comment thread kits/delete-user-data/README.md Resolved
Comment thread kits/delete-user-data/README.md Resolved
…he 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.
… 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.
…data-error-logging

# Conflicts:
#	kits/delete-user-data/CHANGELOG.md
#	kits/delete-user-data/README.md
#	kits/delete-user-data/src/index.ts
#	kits/delete-user-data/tests/index.test.ts
@CorieW
CorieW marked this pull request as ready for review November 9, 2026 16:25
@CorieW
CorieW requested a review from cabljac November 9, 2026 16:25

@cabljac cabljac left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few comments/questions

Comment on lines +152 to +153
if (Date.now() - started >= timeoutMs()) {
return;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this can drop a real failure. timeoutMs() only sees setGlobalOptions, not the timeout the service actually has. The two differ if someone raises the timeout in the console or with gcloud, and with preserveExternalChanges: true the CLI keeps that value on later deploys. The kit then still assumes 60s. If auto-discovery throws at 90s on a service with a 300s timeout, the wrapper returns normally: no ERROR, no stderr stack, and execution_count would record ok. For a deletion kit that looks like a clean delete when it wasn't.

Could we drop the timeout check and always log and rethrow? That also removes timeoutMs() and the param unwrapping. The cost is that a failure after a real timeout shows up in Error Reporting again (the stderr stack), which I think is better than hiding a failure. If we keep the check, logging the late error at WARNING instead of dropping it would at least leave a trace.

Comment on lines +137 to +138
// 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.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Error Reporting already picks up the framework's stderr stack, so this entry adds a second occurrence in the same group rather than making it visible there (the README says as much). Maybe:

Suggested change
// 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.
// severity. Log the error at ERROR severity so log-based alerts see it, then
// rethrow so the invocation still counts as failed.

Comment on lines +286 to +288
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.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Worth saying that per-path failures inside handleClear (firestorePathError, rtdbPathError, storagePathError) still log at ERROR after a timeout. Only an error that escapes the handler is dropped. As written, a reader could take this as "late failures are invisible". If the timeout check goes (see the comment on logFailures), this can just say a late failure is still logged.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

fix(delete-user-data): kit/extension parity – kit failures are logged as HTTP 200 with no error severity

2 participants