Repository: pinojs/pino
Pull request #809 (2020-04-02 05:55:44)

Support formatters.log on pretty print
This is in reference to issue #804.  

I have made an attempt to add support for `formatters.log` while using `prettyPrint: true`, similarly to how `serializers` and `redact` functions are supported.  
I have added a new test with two asserts.
The second assert, which is related to the format action is passing the test.
The first assert however fails, as the log message is not included on the output. This is not a side-effect of this PR, this issue exists even on the current `master`, ie without my submitted modification on tools. 

While returning the original `obj` on `formatters.log`, the log message is present on the pretty print output. Thus with my limited knowledge of the repo, I can only assume that it might be a scope/reference issue with the log object at some other place.


mcollina: cc @delvedor
giannisp: I think it's not too elegant here to have `formatters.log` function responsible for returning/preserving the msg property. As per the original implementation it is supposed to shape the log object only (not including the msg property).
mcollina: This should include a revert of https://github.com/pinojs/pino/commit/4f18f264ba60bcb0536e01613fcff4d92240192e.
giannisp: GitHub hiccup while running the last few CI actions, please trigger a re-run when you get the chance, I don't have enough access.
mcollina: Restarted.
jsumners: > lgtm, @jsumners what do you think?

I am unclear about whether or not `lastMsg` really needed to be reverted.
giannisp: > > lgtm, @jsumners what do you think?
> 
> I am unclear about whether or not `lastMsg` really needed to be reverted.

I have tried encapsulating the msg in lastObj (instead of passing lastMsg), and then unboxing it before applying the `formatters.log`:
```
stream.lastObj = { ...obj, [messageKey]: msg }
```
New test works, however it breaks the pretty/obj-msg-prop test. This illustrates that a log object will have a potential conflict if it has an existing prop named as `messageKey`! So seems safer to keep using `lastMsg`, unless there's another way apart from modifying `obj`.

Patch:
diff --git a/lib/proto.js b/lib/proto.js
index 8e888a6..9c22093 100644
--- a/lib/proto.js
+++ b/lib/proto.js
@@ -163,6 +163,7 @@ function write (_obj, msg, num) {
   if (stream[needsMetadataGsym] === true) {
     stream.lastLevel = num
     stream.lastObj = obj
+    stream.lastMsg = msg
     stream.lastTime = t.slice(this[timeSliceIndexSym])
     stream.lastLogger = this // for child loggers
   }
diff --git a/lib/tools.js b/lib/tools.js
index 7992c30..32ecff4 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -238,12 +238,21 @@ function prettifierMetaWrapper (pretty, dest) {
       }
 
       var lastObj = this.lastObj
+      var lastMsg = this.lastMsg
       var 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
-      }, lastObj, errorProps)
+      }, formattedObj, errorProps)
 
       const serializers = lastLogger[serializersSym]
       const keys = Object.keys(serializers)


Test patch:
diff --git a/test/fixtures/pretty/formatters.js b/test/fixtures/pretty/formatters.js
new file mode 100644
index 0000000..c3a01a0
--- /dev/null
+++ b/test/fixtures/pretty/formatters.js
@@ -0,0 +1,13 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var pino = require(require.resolve('./../../../'))
+var log = pino({
+  prettyPrint: true,
+  formatters: {
+    log (obj) {
+      return { foo: 'formatted_' + obj.foo }
+    }
+  }
+})
+log.info({ foo: 'bar' }, 'h')
diff --git a/test/metadata.test.js b/test/metadata.test.js
index 7fb1c9a..d5c3096 100644
--- a/test/metadata.test.js
+++ b/test/metadata.test.js
@@ -14,6 +14,7 @@ test('metadata works', async ({ ok, same, is }) => {
     write (chunk) {
       is(instance, this.lastLogger)
       is(30, this.lastLevel)
+      is('a msg', this.lastMsg)
       ok(Number(this.lastTime) >= now)
       same(this.lastObj, { hello: 'world', msg: 'a msg' })
       const result = JSON.parse(chunk)
@@ -38,6 +39,7 @@ test('child loggers works', async ({ ok, same, is }) => {
     write (chunk) {
       is(child, this.lastLogger)
       is(30, this.lastLevel)
+      is('a msg', this.lastMsg)
       same(this.lastObj, { from: 'child', msg: 'a msg' })
       const result = JSON.parse(chunk)
       ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
@@ -63,6 +65,7 @@ test('without object', async ({ ok, same, is }) => {
     write (chunk) {
       is(instance, this.lastLogger)
       is(30, this.lastLevel)
+      is('a msg', this.lastMsg)
       same({ msg: 'a msg' }, this.lastObj)
       const result = JSON.parse(chunk)
       ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
diff --git a/test/pretty.test.js b/test/pretty.test.js
index fa86649..be76b65 100644
--- a/test/pretty.test.js
+++ b/test/pretty.test.js
@@ -112,6 +112,19 @@ test('parses and outputs chindings', async ({ is, isNot }) => {
   is(strip(actual).match(/a: 1/g).length, 3)
 })
 
+test('applies formatters', async ({ is, isNot }) => {
+  var actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'pretty', 'formatters.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+  await once(child, 'close')
+  isNot(strip(actual).match(/\(123456 on abcdefghijklmnopqr\): h/), null)
+  isNot(strip(actual).match(/foo: "formatted_bar"/), null)
+})
+
 test('parses and outputs chindings with serializer', async ({ is, isNot }) => {
   var actual = ''
   const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'pretty', 'child-with-serializer.js')])