Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

More Control over Error Logging #484

Open
uhyo opened this issue Nov 16, 2022 · 4 comments
Open

More Control over Error Logging #484

uhyo opened this issue Nov 16, 2022 · 4 comments

Comments

@uhyo
Copy link

uhyo commented Nov 16, 2022

Hello, I started using @google-cloud/functions-framework and noticed that it is not much compatible with structured logging.

Especially, when I use the CloudEventFunction style which seems to be the recommended way when integrating with Cloud Pub/Sub, the function must throw in order to mark the request as failed (i.e. respond with 500).

In that case, the default (and inevitable) error logging isn't quite nice. First, error is logged twice 😨 (1, 2). Second, neither log is not structured, resulting in the error log being split into multiple entries.

スクリーンショット 2022-11-16 17 01 55

I would like to get more control over how errors are logged. Or, maybe as another solution, a method for marking the request as failed without throwing will satisfy my use case.

Thanks!

@jama22 jama22 self-assigned this Nov 16, 2022
@jama22
Copy link

jama22 commented Nov 16, 2022

Hey @uhyo , thanks for bringing this to our attention. I think there's a few things we could do here:

  • we should'nt log it twice
  • we could support structured logging

I think trying to fix the log entry duplication would be a good first issue for someone to fix

The structured logging would be a bit harder and we might not be able to get to that

@flovouin
Copy link

flovouin commented Nov 17, 2022

Duplicate error log
I've noticed the same behaviour as @ uhyo, where the error is logged twice. However even weirder, the log (incorrectly) appears in two different invocations of the function:

Screenshot 2022-11-17 at 15 03 15

Here the first invocation (expectedly) failed because of an uncaught error, meant for the message processing to be retried. The second invocation is the same message being retried (which is expected), and processing succeeds. However the second error log is not only unnecessary as @ uhyo mentioned, but it is tagged with the wrong executionId (see the screenshot). For the record, the two invocations are tagged with the same instance ID.

Unstructured logs
While the errors logged by the functions-framework are indeed unstructured (they are logged with a textPayload), I did not notice them being split in my case. (I redacted the full stack trace for the errors, but it is contained in the same log entry.)

Marking processing as failed without throwing

a method for marking the request as failed without throwing will satisfy my use case.

+1 on this. I currently throw errors to ensure the processing of the Pub/Sub message is eventually retried. However this has several downsides, amongst which:

  • The error is picked up by Error Reporting, but it is not an error that needs fixing. It is only here to trigger a retry.
  • The error is included in the log entry count metrics (logging.googleapis.com/log_entry_count) with the ERROR severity. This can lead to false positives if this metric is used to set up an alert policy.

@jama22, as I understand there is a possible quick fix for part of the issue. Is it worth opening a separate one for the "marking the request as failed without throwing" feature? I'm strongly interested in this one.

@jama22
Copy link

jama22 commented Nov 17, 2022

@flovouin I think that makes a lot of sense to open a separate request for marking the request as failed. We're starting to do some planning next year on how to improve the functions experience when interacting with other GCP services. I think capturing that request in a separate issue will help inform some of our design decisions and get some feedback.

@flovouin
Copy link

@jama22 I've opened a separate issue for the feature request: #488.

Could this one be reclassified as a bug (the error being logged twice), such that it's prioritised a bit higher?

@josephlewis42 josephlewis42 assigned guangyw and unassigned jama22 Jan 17, 2023
@guangyw guangyw removed their assignment Sep 25, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants