"message" argument loses to `mergingObject` when `prettyPrint: true`

[trentm]

The logic that prettifierMetaWrapper uses to decide if mergingObject[messageKey] wins over a "message" field differs from the logic used without prettyPrint:true. The result is that a "msg" field set in formatters.log will override the "message" argument in a log statement, when prettyPrint: true.

For example:

const pino = require('./') // pino
const log = pino({
  formatters: {
    log (obj) {
      obj.formatters_log = 'was here'
      // 1. If a `formatters.log` sets `obj[messageKey]` ...
      if (!obj.msg) {
        obj.msg = '<this is a fallback msg>'
      }
      return { ...obj }
    }
  },
  // 2. ... and `prettyPrint: true` ...
  prettyPrint: !!process.env.PRETTY_PRINT
})

log.info({ stmt: 1, no: 'message' })
// 3. ... then the wrong "msg" will be shown for each of the following:
log.info({ stmt: 2, msg: 'this will not get shown' }, 'this is my message')
log.info({ stmt: 3 }, 'this is my message')

Without prettyPrint, this works as expected (the correct "msg" is in each log record):

% node example-formatters-log.js
{"level":30,"time":1616460170924,"pid":33537,"hostname":"pink.local","stmt":1,"no":"message","formatters_log":"was here","msg":"<this is a fallback msg>"}
{"level":30,"time":1616460170925,"pid":33537,"hostname":"pink.local","stmt":2,"msg":"this is my message","formatters_log":"was here"}
{"level":30,"time":1616460170925,"pid":33537,"hostname":"pink.local","stmt":3,"formatters_log":"was here","msg":"this is my message"}

However, with prettyPrint:true we get the wrong "msg" field for 2nd and 3rd log records:

% PRETTY_PRINT=1 node example-formatters-log.js
[1616460330959] INFO (33591 on pink.local): <this is a fallback msg>
    stmt: 1
    no: "message"
    formatters_log: "was here"
[1616460330962] INFO (33591 on pink.local): this will not get shown
    stmt: 2
    formatters_log: "was here"
[1616460330962] INFO (33591 on pink.local): <this is a fallback msg>
    stmt: 3
    formatters_log: "was here"

First pass fix

The issue is that prettifierMetaWrapper is deciding to not use lastMsg if formattedObj.hasOwnProperty(messageKey), rather than use lastMsg if it is defined. With the following change:

diff --git a/lib/tools.js b/lib/tools.js
index c405a27..bb8f9a4 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -247,16 +247,16 @@ function prettifierMetaWrapper (pretty, dest, opts) {
       const formatters = lastLogger[formattersSym]
       const formattedObj = formatters.log ? formatters.log(lastObj) : lastObj

-      const messageKey = lastLogger[messageKeySym]
-      if (lastMsg && formattedObj && !formattedObj.hasOwnProperty(messageKey)) {
-        formattedObj[messageKey] = lastMsg
-      }
-
       const obj = Object.assign({
         level: this.lastLevel,
         time
       }, formattedObj, errorProps)

+      const messageKey = lastLogger[messageKeySym]
+      if (lastMsg !== undefined) {
+        obj[messageKey] = lastMsg
+      }
+
       const serializers = lastLogger[serializersSym]
       const keys = Object.keys(serializers)

We get the expected behaviour:

% PRETTY_PRINT=1 node example-formatters-log.js
[1616460609952] INFO (33738 on pink.local): <this is a fallback msg>
    stmt: 1
    no: "message"
    formatters_log: "was here"
[1616460609954] INFO (33738 on pink.local): this is my message
    stmt: 2
    formatters_log: "was here"
[1616460609955] INFO (33738 on pink.local): this is my message
    stmt: 3
    formatters_log: "was here"

Second pass fix

Looking back at the source issue for the change that introduced the !formattedObj.hasOwnProperty(messageKey) logic, it stated:

pretty print does not apply formatters.log function (like it does with serializers and redact functions).

I'm not sure that was actually an issue at the time. At least I don't believe it is in current master. Issue #866 points out that formatters.log is being called a second time on log records when prettyPrint: true. I believe #866 could also be handled with this diff:

diff --git a/lib/tools.js b/lib/tools.js
index c405a27..6342adc 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -240,22 +240,18 @@ function prettifierMetaWrapper (pretty, dest, opts) {
         time = time.slice(1, -1)
       }

-      const lastObj = this.lastObj
-      const lastMsg = this.lastMsg
       const errorProps = null

-      const formatters = lastLogger[formattersSym]
-      const formattedObj = formatters.log ? formatters.log(lastObj) : lastObj
-
-      const messageKey = lastLogger[messageKeySym]
-      if (lastMsg && formattedObj && !formattedObj.hasOwnProperty(messageKey)) {
-        formattedObj[messageKey] = lastMsg
-      }
-
       const obj = Object.assign({
         level: this.lastLevel,
         time
-      }, formattedObj, errorProps)
+      }, this.lastObj, errorProps)
+
+      const lastMsg = this.lastMsg
+      const messageKey = lastLogger[messageKeySym]
+      if (lastMsg !== undefined) {
+        obj[messageKey] = lastMsg
+      }

       const serializers = lastLogger[serializersSym]
       const keys = Object.keys(serializers)

We still get the expected "msg" value for the example-formatters-log.js above, and the test suite still passes.

Does this all sound reasonable? Shall I submit a PR with the above change?

[trentm]

To answer why a formatters.log would set a "fallback msg" value: This came up in https://github.com/elastic/ecs-logging-nodejs/issues/73 as a result of this change: https://github.com/elastic/ecs-logging-nodejs/commit/da055659e63cd0182ab2a7e7c2bb4934a01f6ccb

The @elastic/ecs-pino-format is a package to configure pino for output logs in ecs-logging format. One of the requirements of that format is that the message field always exists. To handle the case log.info({foo: 'bar'}) where there is no message, this package uses formatters.log to set the message field to the empty string as a fallback.

[mcollina]

The reasoning and proposed fix sounds good, go ahead with the PR.

(thanks for the work you did on Bunyan @trentm, you have been a great inspiration to myself and Pino)

[trentm]

thanks for the work you did on Bunyan

Thanks for saying so. You've done a great job on pino.

[Fdawgs]

@trentm Did you manage to resolve this?

[trentm]

@Fdawgs Sorry, no, I never got back to this. I may in the future, but I can re-evaluate and re-open this if so.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.