Log formatter getting called twice - intentional?

[KidkArolis]

Hi! Trying to understand if it's intentional that the formatter.log gets called twice:

https://github.com/pinojs/pino/blob/faf7cb85fe645cfec08a12b46ea0dc21c0f77f11/lib/proto.js#L160-L171

• first time via line 160
• second time via line 171

I'm mutating the object being logged (should I not be?) and it's causing some unexpected output.

[jsumners]

I don't understand the issue. Line 160 is running the object and message through the JSON serializer. Line 171 is writing the actual generated log line, as a single string primitive, to the destination stream.

Can you provide a replication of your issue?

[KidkArolis]

I've looked a bit more into it, it's only happening when pretty printing is enabled, e.g.:

const pino = require('pino')

const logger = pino({
  prettyPrint: true
})

const child = logger.child({
  formatters: {
    log(obj) {
      console.log('Formatting log', obj)
      obj.replacement = obj.missing
      delete obj.missing
      return obj
    }
  }
})

child.info({ missing: 'a', works: 'hello' }, 'Only logging once')

Outputs:

Formatting log { missing: 'a', works: 'hello' }
Formatting log { works: 'hello', replacement: 'a', msg: 'Only logging once' }
[1593173703575] INFO  (7085 on inrainbows.local): Only logging once
    works: "hello"

Notice that:

1. We log once, but formatting happens twice
2. Notice that the final log output has neither missing nor replacement key (!?)

[jsumners]

@delvedor is this double invocation expected with the formatter implementation you added?

[mcollina]

There might be a bug in how formatters.log is handled in prettyPrint, or it might also be the only way we could make it work. Pino has a lot of options and some might conflict. Feel free to send a PR if you understand what's happening.