Investigate textPayload population and double-quoting in logger

[mbleigh]

See comments in #665.

[mbleigh]

@sk- I believe this is working as intended...ish...in that textPayload is populated if there is no structured data added as a final argument to the log. In the Cloud Logging console I believe the double-quotes are there when the message is being lifted from jsonPayload generally, not as any kind of actual extra quoting happening (the "classic" view doesn't do the same so it seems to be a UX choice).

Can you describe how you have your metrics set up now so I can think through how we might be able to make compat more...compatible? Perhaps compat should not use structured data at all and just put everything into the textPayload trying to better mimic what we have today in Node 8...

[sk-]

Thanks @mbleigh for looking into this. I tested again, and you are right, if you only have the severity and message field, then the log is treated like an unstructured log and you get textPayload populated (and no quotes in the UI).

However, the log docs, don't mention anything about this special case.

Some of our metrics, just perform a query on textPayload. For example to detect errors in our services.

This means that if a developer inadvertently converts a log from:

console.warn(`Got unexpected ${id}`)

to something like

console.warn(`Got unexpected ${id}`, {extra_data: 1, id: 23})

then those logs won't be captured by the metric, unless I change it to read from both textPayload and jsonPayload.message

It'd be great if textPayload could always be set, either to jsonPayload.message or to the whole JSON entry.

I also think that maybe compat should not accept structured data, because of 3 issues:

1. errors are instance of object, and today is quite common to do console.error(error) when catching an exception. With compat that would be shown as structured data. And may loose the stack trace.
2. I've seen code like this console.log('Messsage', data), which todays logs to multiple lines, as unstructured data. (I know this is awful and makes logs quite hard to read)
3. With compat, entries with new line will correspond to one log entry. Whereas today they correspond to multiple ones. (This one is arguably much better behavior, but still different to what happens today and could also break queries).

[mbleigh]

So (3) is definitely intended -- Node 8 is able to do multi-line output as a single entry, it's actually Node 10 that broke this behavior. If you want the behavior of every newline being a separate entry, you don't need to use the new logging API you can just use console.*.

I think (1) is a good point -- but have you tested this? I believe the code is testing for plain objects before treating it as structured data. An error might behave appropriately, but I'd need to double-check.

(2) is also a good point, and I think it might be reasonable to treat the compat behavior as never doing structured data since it is explicitly a compatibility layer. The new API can keep doing structured data with the expectation that you may need to change your queries.

I'll hold off on releasing the new logging API until I've had a little more time to talk with folks internally about the points you've raised here.

[sk-]

You are right about 1). I missed the constructor check, which for the case of Errors is not Object.

With respect to 3) I agree that is much better, but if you use compat then you don't have an alternative, other than manually splitting the entry. Note that I prefer this behavior, but may be surprising for someone using compat. Maybe in the notes, you could add a warning.

[kitfit-dave]

If I could chime in here are about (2) I would agree that it would be most reasonable for compat to never do structured data - for me the compat stuff should be for people just wanting their old console.log stuff to go back to working like it did on node 8. If they want structured logging they should use the logging sdk. I.e. go for less magic. And I do agree that stuff like console.log('Messsage', data) is horrible and stuctured logging is objectively better, but realistically, it's what a lot of us will be working with.

My game plan here for our firebase functions code would be: use compat for now so our existing stuff works again; for new functions make sure to use the logging SDK; eventually circle back and change everything to the new shiny structured logging (an easier(er) sell once everyone sees how good the new logs look).

[kitfit-dave]

Oh, and if it wasn't obvious, I do still think that (3) is rightly "as intended" and should be a basic functionality/requirement of compat - make multiline logs come out at as single line. This is just to restore the pre node 10 funtionality. Anyone wanting them to come out as multiple log entries should not use compat.

[mbleigh]

This has been released in v3.7.0 with as much Node 8 compat as we can muster. See release notes: https://github.com/firebase/firebase-functions/releases/tag/v3.7.0

[jankalthoefer]

Hey everyone :)
I am struggling right now with getting structured logs when using the firebase emulator.
I tried with firebase-functions@3.7.0 and also updated to @3.11.0, without improvements.

Does the logs in the emulator maybe differ from those in the cloud environment.

Thanks in advance for any help!