Repository: pinojs/pino (js)

Issue:
Properly handling the 'nestedKey' option
Let me start by congratulating you guys on this awesome project and by saying I have read #872, #771 and #792 and the docs available [here](https://github.com/pinojs/pino/blob/master/docs/api.md#nestedkey-string).

Personally what I understand from the docs (and what I would expect to happen) is that the serializers will still receive the original object, not the one after the 'nestedKey' transformation (as the base is static, the dynamic part is the passed object and the serializers register only on root level properties, making the serializers register feature pointless when used with 'nestedKey'). But this is my opinion and is subject to interpretation.

However, activating the 'nestedKey' option breaks the standard serialization of errors (because the detection fails) which is a bug (standard options should not break each other).

The problem seems to be that the passed object is transformed [here](https://github.com/pinojs/pino/blob/83d80f63888aa0b68479d460706644c58257131c/lib/tools.js#L47) and afterwards is checked for it's type [here](https://github.com/pinojs/pino/blob/83d80f63888aa0b68479d460706644c58257131c/lib/proto.js#L144) effectively transforming all Errors into plain objects so the detection is never true.

I think it would be a good idea to do the transformation after the check.

If you guys agree I would be happy to make a PR.




Pull request description:
Make the nestedKey only take effect in the serialized object and fix …
…error detection and serialization (closes #883)

proto.js
* Copy the message property in case the obj is an error and there is a msg specified
* Load the msg as a property of obj if metadata is needed

symbols.js
* Add nestedKeyStrSym to quickly cache the string

tools.js
* Manually build the stringify for performance reasons (not too pretty...)

error.test.js + serializers.test.js
* Add a test for the new nestedKey interaction

Patch:
diff --git a/lib/symbols.js b/lib/symbols.js
index 880cee2..226d791 100644
--- a/lib/symbols.js
+++ b/lib/symbols.js
@@ -24,6 +24,7 @@ const endSym = Symbol('pino.end')
 const formatOptsSym = Symbol('pino.formatOpts')
 const messageKeySym = Symbol('pino.messageKey')
 const nestedKeySym = Symbol('pino.nestedKey')
+const nestedKeyStrSym = Symbol('pino.nestedKeyStr')
 
 const wildcardFirstSym = Symbol('pino.wildcardFirst')
 
@@ -60,5 +61,6 @@ module.exports = {
   needsMetadataGsym,
   useOnlyCustomLevelsSym,
   formattersSym,
-  hooksSym
+  hooksSym,
+  nestedKeyStrSym
 }
diff --git a/lib/tools.js b/lib/tools.js
index a7c9389..a357cab 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -22,7 +22,8 @@ const {
   streamSym,
   nestedKeySym,
   formattersSym,
-  messageKeySym
+  messageKeySym,
+  nestedKeyStrSym
 } = require('./symbols')
 
 function noop () {}
@@ -44,7 +45,6 @@ function genLog (level, hook) {
           o = mapHttpResponse(o)
         }
       }
-      if (this[nestedKeySym]) o = { [this[nestedKeySym]]: o }
       let formatParams
       if (msg === null && n.length === 0) {
         formatParams = [null]
@@ -108,10 +108,8 @@ function asJson (obj, msg, num, time) {
   if (formatters.log) {
     obj = formatters.log(obj)
   }
-  if (msg !== undefined) {
-    obj[messageKey] = msg
-  }
   const wildcardStringifier = stringifiers[wildcardFirstSym]
+  let propStr = ''
   for (const key in obj) {
     value = obj[key]
     if ((notHasOwnProperty || obj.hasOwnProperty(key)) && value !== undefined) {
@@ -139,11 +137,45 @@ function asJson (obj, msg, num, time) {
           value = (stringifier || stringify)(value)
       }
       if (value === undefined) continue
-      data += ',"' + key + '":' + value
+      propStr += ',"' + key + '":' + value
+    }
+  }
+
+  let msgStr = ''
+  if (msg !== undefined) {
+    value = serializers[messageKey] ? serializers[messageKey](msg) : msg
+    const stringifier = stringifiers[messageKey] || wildcardStringifier
+
+    switch (typeof value) {
+      case 'function':
+        break
+      case 'number':
+        /* eslint no-fallthrough: "off" */
+        if (Number.isFinite(value) === false) {
+          value = null
+        }
+      // this case explicitly falls through to the next one
+      case 'boolean':
+        if (stringifier) value = stringifier(value)
+        msgStr = ',"' + messageKey + '":' + value
+        break
+      case 'string':
+        value = (stringifier || asString)(value)
+        msgStr = ',"' + messageKey + '":' + value
+        break
+      default:
+        value = (stringifier || stringify)(value)
+        msgStr = ',"' + messageKey + '":' + value
     }
   }
 
-  return data + end
+  if (this[nestedKeySym]) {
+    // place all the obj properties under the specified key
+    // the nested key is already formatted from the constructor
+    return data + this[nestedKeyStrSym] + propStr.slice(1) + '}' + msgStr + end
+  } else {
+    return data + propStr + msgStr + end
+  }
 }
 
 function asChindings (instance, bindings) {
diff --git a/pino.js b/pino.js
index 05dddf2..7215fdc 100644
--- a/pino.js
+++ b/pino.js
@@ -34,7 +34,8 @@ const {
   mixinSym,
   useOnlyCustomLevelsSym,
   formattersSym,
-  hooksSym
+  hooksSym,
+  nestedKeyStrSym
 } = symbols
 const { epochTime, nullTime } = time
 const { pid } = process
@@ -171,6 +172,8 @@ function pino (...args) {
     [formatOptsSym]: formatOpts,
     [messageKeySym]: messageKey,
     [nestedKeySym]: nestedKey,
+    // protect against injection
+    [nestedKeyStrSym]: nestedKey ? `,${JSON.stringify(nestedKey)}:{` : '',
     [serializersSym]: serializers,
     [mixinSym]: mixin,
     [chindingsSym]: chindings,


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index 11e3230..43fb8ed 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -673,3 +673,36 @@ test('offers a .default() method to please typescript', async ({ equal }) => {
   instance.info('hello world')
   check(equal, await once(stream, 'data'), 30, 'hello world')
 })
+
+test('correctly skip function', async (t) => {
+  const stream = sink()
+  const instance = pino(stream)
+
+  const o = { num: NaN }
+  instance.info(o, () => {})
+
+  const { msg } = await once(stream, 'data')
+  t.is(msg, undefined)
+})
+
+test('correctly skip Infinity', async (t) => {
+  const stream = sink()
+  const instance = pino(stream)
+
+  const o = { num: NaN }
+  instance.info(o, Infinity)
+
+  const { msg } = await once(stream, 'data')
+  t.is(msg, null)
+})
+
+test('correctly log number', async (t) => {
+  const stream = sink()
+  const instance = pino(stream)
+
+  const o = { num: NaN }
+  instance.info(o, 42)
+
+  const { msg } = await once(stream, 'data')
+  t.is(msg, 42)
+})
diff --git a/test/error.test.js b/test/error.test.js
index 0f357d8..a0da655 100644
--- a/test/error.test.js
+++ b/test/error.test.js
@@ -320,3 +320,55 @@ test('empty serializer', async ({ same }) => {
     msg: err.message
   })
 })
+
+test('correctly adds error information when nestedKey is used', async ({ same }) => {
+  const err = new Error('myerror')
+  err.toString = () => undefined
+  const stream = sink()
+  const instance = pino({
+    test: 'this',
+    nestedKey: 'obj'
+  }, stream)
+  instance.fatal(err)
+  const result = await once(stream, 'data')
+  delete result.time
+  same(result, {
+    pid,
+    hostname,
+    level: 60,
+    obj: {
+      err: {
+        type: 'Error',
+        stack: err.stack,
+        message: err.message
+      }
+    },
+    msg: err.message
+  })
+})
+
+test('correctly adds msg on error when nestedKey is used', async ({ same }) => {
+  const err = new Error('myerror')
+  err.toString = () => undefined
+  const stream = sink()
+  const instance = pino({
+    test: 'this',
+    nestedKey: 'obj'
+  }, stream)
+  instance.fatal(err, 'msg message')
+  const result = await once(stream, 'data')
+  delete result.time
+  same(result, {
+    pid,
+    hostname,
+    level: 60,
+    obj: {
+      err: {
+        type: 'Error',
+        stack: err.stack,
+        message: err.message
+      }
+    },
+    msg: 'msg message'
+  })
+})
diff --git a/test/metadata.test.js b/test/metadata.test.js
index 4ab770d..1330973 100644
--- a/test/metadata.test.js
+++ b/test/metadata.test.js
@@ -16,7 +16,7 @@ test('metadata works', async ({ ok, same, equal }) => {
       equal(30, this.lastLevel)
       equal('a msg', this.lastMsg)
       ok(Number(this.lastTime) >= now)
-      same(this.lastObj, { hello: 'world', msg: 'a msg' })
+      same(this.lastObj, { hello: 'world' })
       const result = JSON.parse(chunk)
       ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
       delete result.time
@@ -40,7 +40,7 @@ test('child loggers works', async ({ ok, same, equal }) => {
       equal(child, this.lastLogger)
       equal(30, this.lastLevel)
       equal('a msg', this.lastMsg)
-      same(this.lastObj, { from: 'child', msg: 'a msg' })
+      same(this.lastObj, { from: 'child' })
       const result = JSON.parse(chunk)
       ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
       delete result.time
@@ -66,7 +66,7 @@ test('without object', async ({ ok, same, equal }) => {
       equal(instance, this.lastLogger)
       equal(30, this.lastLevel)
       equal('a msg', this.lastMsg)
-      same({ msg: 'a msg' }, this.lastObj)
+      same({ }, this.lastObj)
       const result = JSON.parse(chunk)
       ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
       delete result.time
diff --git a/test/multistream.test.js b/test/multistream.test.js
index f5d49a0..463be48 100644
--- a/test/multistream.test.js
+++ b/test/multistream.test.js
@@ -271,7 +271,7 @@ test('levelVal ovverides level', function (t) {
 })
 
 test('forwards metadata', function (t) {
-  t.plan(3)
+  t.plan(4)
   const streams = [
     {
       stream: {
@@ -279,7 +279,8 @@ test('forwards metadata', function (t) {
         write (chunk) {
           t.equal(log, this.lastLogger)
           t.equal(30, this.lastLevel)
-          t.same({ hello: 'world', msg: 'a msg' }, this.lastObj)
+          t.same({ hello: 'world' }, this.lastObj)
+          t.same('a msg', this.lastMsg)
         }
       }
     }
diff --git a/test/redact.test.js b/test/redact.test.js
index 26a9895..3589141 100644
--- a/test/redact.test.js
+++ b/test/redact.test.js
@@ -775,3 +775,15 @@ test('child bindings are redacted using wildcard and plain path keys', async ({
   equal(req.headers.cookie, '[Redacted]')
   equal(req.method, '[Redacted]')
 })
+
+test('redacts boolean at the top level', async ({ is }) => {
+  const stream = sink()
+  const instance = pino({ redact: ['msg'] }, stream)
+  const obj = {
+    s: 's'
+  }
+  instance.info(obj, true)
+  const o = await once(stream, 'data')
+  is(o.s, 's')
+  is(o.msg, '[Redacted]')
+})
diff --git a/test/serializers.test.js b/test/serializers.test.js
index 31d098d..5fef8e4 100644
--- a/test/serializers.test.js
+++ b/test/serializers.test.js
@@ -44,6 +44,29 @@ test('custom serializer overrides default err namespace error serializer', async
   equal(typeof o.err.s, 'string')
 })
 
+test('custom serializer overrides default err namespace error serializer when nestedKey is on', async ({ equal }) => {
+  const stream = sink()
+  const parent = pino({
+    nestedKey: 'obj',
+    serializers: {
+      err: (e) => {
+        return {
+          t: e.constructor.name,
+          m: e.message,
+          s: e.stack
+        }
+      }
+    }
+  }, stream)
+
+  parent.info({ err: ReferenceError('test') })
+  const o = await once(stream, 'data')
+  equal(typeof o.obj.err, 'object')
+  equal(o.obj.err.t, 'ReferenceError')
+  equal(o.obj.err.m, 'test')
+  equal(typeof o.obj.err.s, 'string')
+})
+
 test('null overrides default err namespace error serializer', async ({ equal }) => {
   const stream = sink()
   const parent = pino({ serializers: { err: null } }, stream)
@@ -214,3 +237,14 @@ test('non-overridden serializers are available in the children', async ({ equal
   parent.fatal({ onlyChild: 'test' })
   equal((await o4).onlyChild, 'test')
 })
+
+test('custom serializer for messageKey', async (t) => {
+  const stream = sink()
+  const instance = pino({ serializers: { msg: () => '422' } }, stream)
+
+  const o = { num: NaN }
+  instance.info(o, 42)
+
+  const { msg } = await once(stream, 'data')
+  t.is(msg, '422')
+})