GoogleCloudPlatform / functions-framework-nodejs

FaaS (Function as a service) framework for writing portable Node.js functions
Apache License 2.0
1.29k stars 158 forks source link

More Control over Error Logging #484

Open uhyo opened 1 year ago

uhyo commented 1 year ago

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 commented 1 year ago

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

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 commented 1 year ago

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:

@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 commented 1 year ago

@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 commented 1 year ago

@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?