Setting message to empty string breaks formatting with pino-pretty

[jdelight]

Hey there, I've just updated to version 1.1.0 (pino ) and it seems the change to set an empty message property breaks formatting.

I'm also using pino-pretty to format logs.

The issues seems to be here:

      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
      }

lastObj is passed to the ecs log formatter which then sets a message property on it to empty string

the comment about the line above indicates the message as empty string is set because a message is not present on the object. However, from the code above, message has been separated from the rest of the log object and is not passed into the log formatter at all.

Also from the description of how the log formatter works - the message is intentionally not passed in.

The end result is that when the if statement runs if (lastMsg && formattedObj && !formattedObj.hasOwnProperty(messageKey)) {...} it always returns true because formattedObj now does have a message property.

Simple test case:

using the examples/express-simple.js in this repo - install pino-pretty and set prettyPrint: true on the logger config:

const log = pino({ ...ecsFormat({ convertReqRes: true }), prettyPrint: true })

then when running node express-simple.js you should see something like this (note message regarding the server listening is missing):

[timestamp] INFO:
    ecs: {
      "version": "1.6.0"
    }
    process: {
      "pid": ...
    }
    host: {
      "hostname": "..."
    }

I'm not 100% sure if this is a pino-pretty issue or an ecs format issue - but the update to 1.1.0 seems to have broken what was working so thought I'd raise it here.

[trentm]

@jdelight Thanks for the ticket! Interesting.

According to https://getpino.io/#/docs/api?id=message-string the "message" argument in a log statement should win over a message attribute on the mergedObject:

The message parameter takes precedence over the mergedObject. That is, if a mergedObject contains a msg property, and a message parameter is supplied in addition, the msg property in the output log will be the value of the message parameter not the value of the msg property on the mergedObject.

% node
> var pino = require('pino')
undefined
> var log = pino({level: 'info'})
undefined
> log.info({foo: 'bar', msg: 'not going to show this'}, 'this is my message')
{"level":30,"time":1616454887141,"pid":29011,"hostname":"pink.local","foo":"bar","msg":"this is my message"}
undefined

That is based on the test whether the "message" argument is undefined: https://github.com/pinojs/pino/blob/35b13d24594da16e986b10ca256eb5061a5f44b9/lib/tools.js#L108-L113

However, the logic for deciding if a "message" argument wins in prettifierMetaWrapper is using formattedObj.hasOwnProperty(messageKey). https://github.com/pinojs/pino/blob/35b13d24594da16e986b10ca256eb5061a5f44b9/lib/tools.js#L250-L253
This was added in pinojs/pino#809

I think I'd call this a bug in pino's prettifierMetaWrapper, but I'll open a ticket on the pino repo to discuss with its maintainers.

In the meantime, I'm sorry this breaks your use case. If reasonable for your usage, I have a start at a pretty-printer alternative to pino-pretty that supports the ECS logging format: https://github.com/trentm/go-ecslog
It is out of process, however, so might not be as handy for you.

FWIW, here is my potential fix to pino:

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)

[jdelight]

Thanks @trentm - that all makes sense. I'll keep a look out for any further discussions on pino/pino-pretty. In the meantime I've wrapped the formatter.log to remove the message key. But will update if a fix (like yours above) is implemented.

[trentm]

I'll follow through on that pino PR. However, with elastic/ecs-logging#55 I think we'll remove the requirement that ecs-logging records have a "message" field. Once that is in, I can drop the setting of the fallback empty string for "message". That'll solve this issue.

[trentm]

@jdelight @elastic/ecs-pino-format@1.1.1 is published, which should have the fix for you.

[jdelight]

That's awesome - thanks @trentm 👍