`message` field in data record overwrites actual log message

[yelworc]

When a message property is included in the log data payload (ie. the first parameter of the logger call, see example below), that field overrides the actual log message (provided as the second parameter). I realize that this might be hard to "fix" – the only ugly workaround I can think of at the moment would be automatically renaming the data field to something like _message…

If you consider this a user error, I think a caveat/warning in the docs would be appropriate.

Environment details

• OS: Debian 5.10.158-2
• Node.js version: v18.12.1
• npm version: 8.19.2
• @google-cloud/logging-bunyan version: 4.2.2

Steps to reproduce

1. Log a message like this:

logger.info({ message: 'boom' }, 'this is the actual message');

[yelworc]

This is kinda related to #515 I guess; another solution might be putting the "real" message in textPayload instead of jsonPayload.message. That would obviously be a breaking change, or need to be optional behavior enabled by a config flag.

[cindy-peng]

Hi @yelworc , unfortunately this is the expected behavior for nodejs-logging-bunyan library. Nodejs-logging-bunyan provides an easy to use layer for working with Cloud Logging using Bunyan. For cloud logging, we try not to modify bunyan json log entries to be consistent with other bunyan streams. That's why the provided payload message will still be logged as jsonPayload.message in Cloud logging.

I tried to repro the scenario here. The payload message field was actually not overwriting the actual message. If you use log explorer, you can expand the log entries and still find the actual message under jsonPayload.msg:

However when you view logs in log explorer, logging uses message key from a structured log entry as the summary of the log entry when the entry isn't expanded: https://cloud.google.com/logging/docs/write-query-log-entries-gcloud#explore That's probably why it looks like the message has been overwritten.

If you want to view both payload message and actual message without expanding the log entry, you can customize the summary to include both fields in log explorer:

[yelworc]

Thx for the response @cindy-peng!

I noticed the msg field, but that feels somewhat inconsistent – it's only there if the data payload contains a message property. Or, in fact, if it is an error:

logger.info(new Error('boom'), 'something broke');

which results in the entire stack trace being used as the primary message, making the UI a bit confusing:

But of course there are always going to be conflicts when mapping one data structure to another one, where both have their own "special" fields.

Is there a way to reconfigure what the GCL UI uses as the "primary" log message (i.e. the string it displays in unexpanded rows)? I think all I'd want would be for it to show jsonPayload.msg instead of jsonPayload.message if it exists 🙂

[cindy-peng]

Thanks @yelworc! As you have already figured,message field is a special field for structured logging, along with other fields including severity and labels:

• https://cloud.google.com/logging/docs/structured-logging#special-payload-fields
• https://cloud.google.com/functions/docs/monitoring/logging#processing_special_json_fields_in_messages

It is also by design to report the entire trace when there is an error, which is to allow cloud error reporting to pick up errors:
https://github.com/googleapis/nodejs-logging-bunyan/blob/main/src/index.ts#L263

In GCL UI, we don't support customize for primary log message, only the summary fields can be customized: https://cloud.google.com/logging/docs/view/logs-explorer-interface#add_summary_fields.

Unfortunately in your case, I think the only way to keep the actual message in the log entry line is to avoid overwriting those special fields in the payload. I will update the documentation to explain more about this.

[yelworc]

Thanks for the explanation! And your docs addition makes sense to me, FWIW :)