Repository: pinojs/pino (js)

Issue:
Including `msg` in object and string leads to silent data loss
To reproduce:

```
const pino = require('pino')();
pino.info({"msg":"OBJ"},"STRING")
```

The result is that "STRING" is logged and "OBJ" is silently discarded.

This could happen when you use `pino.info(obj)` on an object that happens to have a `msg` property.

The recommended fix when `msg` appears in the object and the string is to throw an error. The current behavior is silent data loss.

There's nothing worse than going to check your logs for some critical detail about a past event only to find it was silently discarded by your logging library and you can't retroactively fix it. If you've got an object that contains a msg property that you want to log, instead of:

    log.info(obj)

You can do:

    log.info({obj}).

The error thrown for the duplicate `msg` case could explain that.

Pull request:
Avoid data loss with conflictig 'msg' values.
If msg appears as a string and in the object, preserve it as "originalMsg"

Before, the `msg` copy in the the object was lost.

Fixes #874

`npm run bench-basic` reports results within about a millisecond before and after this change, which is within the margin of arability on my laptop. 

Patch:
diff --git a/docs/api.md b/docs/api.md
index cafacdf..18e7424 100644
--- a/docs/api.md
+++ b/docs/api.md
@@ -488,6 +488,8 @@ 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`.
+In case this conflict occurs, the `msg` property from the object will be preserved
+in the key `originalMsg`.
 
 The `messageKey` option can be used at instantiation time to change the namespace
 from `msg` to another string as preferred.
diff --git a/lib/levels.js b/lib/levels.js
index 494368e..e553bff 100644
--- a/lib/levels.js
+++ b/lib/levels.js
@@ -112,7 +112,8 @@ function setLevel (level) {
 
 function getLevel (level) {
   const { levels, levelVal } = this
-  return levels.labels[levelVal]
+  // protection against potential loss of Pino scope from serializers (edge case with circular refs - https://github.com/pinojs/pino/issues/833)
+  return (levels && levels.labels) ? levels.labels[levelVal] : ''
 }
 
 function isLevelEnabled (logLevel) {
diff --git a/lib/proto.js b/lib/proto.js
index 23348e1..e08ea4a 100644
--- a/lib/proto.js
+++ b/lib/proto.js
@@ -64,7 +64,10 @@ const prototype = {
 
 Object.setPrototypeOf(prototype, EventEmitter.prototype)
 
-module.exports = prototype
+// exporting and consuming the prototype object using factory pattern fixes scoping issues with getters when serializing
+module.exports = function () {
+  return Object.create(prototype)
+}
 
 const resetChildingsFormatter = bindings => bindings
 function child (bindings) {
diff --git a/lib/tools.js b/lib/tools.js
index f45f898..00b7ab0 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -109,6 +109,10 @@ function asJson (obj, msg, num, time) {
     obj = formatters.log(obj)
   }
   if (msg !== undefined) {
+    // If msg appears as a string and in the object, preserve it as "originalMsg"
+    if (obj[messageKey] !== undefined) {
+      obj.originalMsg = obj[messageKey]
+    }
     obj[messageKey] = msg
   }
   const wildcardStringifier = stringifiers[wildcardFirstSym]
diff --git a/pino.js b/pino.js
index 2c5a5f1..5052109 100644
--- a/pino.js
+++ b/pino.js
@@ -169,7 +169,8 @@ function pino (...args) {
     [hooksSym]: hooks,
     silent: noop
   })
-  Object.setPrototypeOf(instance, proto)
+
+  Object.setPrototypeOf(instance, proto())
 
   genLsCache(instance)
 


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index fa29c33..5f0ecd8 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -141,6 +141,7 @@ function levelTest (name, level) {
       hostname,
       level,
       msg: 'string',
+      originalMsg: 'object',
       hello: 'world'
     })
   })
diff --git a/test/levels.test.js b/test/levels.test.js
index a71cfd3..ed86c83 100644
--- a/test/levels.test.js
+++ b/test/levels.test.js
@@ -4,6 +4,8 @@ const { test } = require('tap')
 const { sink, once, check } = require('./helper')
 const pino = require('../')
 
+const levelsLib = require('../lib/levels')
+
 // Silence all warnings for this test
 process.removeAllListeners('warning')
 process.on('warning', () => {})
@@ -550,3 +552,10 @@ test('changing level from info to silent and back to info in child logger', asyn
   result = await once(stream, 'data')
   check(is, result, expected.level, expected.msg)
 })
+
+// testing for potential loss of Pino constructor scope from serializers - an edge case with circular refs see:  https://github.com/pinojs/pino/issues/833
+test('trying to get levels when `this` is no longer a Pino instance returns an empty string', async ({ is }) => {
+  const notPinoInstance = { some: 'object', getLevel: levelsLib.getLevel }
+  const blankedLevelValue = notPinoInstance.getLevel()
+  is(blankedLevelValue, '')
+})