Repository: pinojs/pino
Pull request #224 (2017-03-23 00:05:47)

Make sure child bindings are logged before objects
This PR is to fix issue #222.


Patch:
diff --git a/browser.js b/browser.js
index 8de3f31..5639b50 100644
--- a/browser.js
+++ b/browser.js
@@ -45,7 +45,6 @@ function pino (opts) {
       throw new Error('missing bindings for child Pino')
     }
     function Child (parent) {
-      this._childLevel = (parent._childLevel | 0) + 1
       this.error = bind(parent, bindings, 'error')
       this.fatal = bind(parent, bindings, 'fatal')
       this.warn = bind(parent, bindings, 'warn')
@@ -70,16 +69,10 @@ function asObject (logger, levels) {
         for (var i = 0; i < args.length; i++) args[i] = arguments[i]
         var msg = args[0]
         var o = { time: Date.now(), level: pino.levels.values[k] }
-        var lvl = (this._childLevel | 0) + 1
-        if (lvl < 1) lvl = 1
         // deliberate, catching objects, arrays
-        if (msg !== null && typeof msg === 'object') {
-          while (lvl-- && typeof args[0] === 'object') {
-            Object.assign(o, args.shift())
-          }
-          msg = args.length ? format(args) : undefined
-        } else if (typeof msg === 'string') msg = format(args)
-        if (msg !== undefined) o.msg = msg
+        if (msg !== null && typeof msg === 'object') Object.assign(o, msg)
+        if (typeof msg === 'string') msg = format(args)
+        o.msg = msg
         write.call(logger, o)
       }
     })(logger[k], k)
@@ -121,7 +114,7 @@ function bind (parent, bindings, level) {
     for (var i = 1; i < args.length; i++) {
       args[i] = arguments[i - 1]
     }
-    return parent[level].apply(this, args)
+    return parent[level].apply(null, args)
   }
 }
 
diff --git a/package.json b/package.json
index a04780c..831ff3d 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "pino",
-  "version": "4.2.1",
+  "version": "4.2.0",
   "description": "super fast, all natural json logger",
   "main": "pino.js",
   "browser": "./browser.js",
diff --git a/pino.js b/pino.js
index 614fa16..ac98c2e 100644
--- a/pino.js
+++ b/pino.js
@@ -123,6 +123,9 @@ function asJson (obj, msg, num) {
   if (msg != undefined) {
     data += ',"msg":' + JSON.stringify('' + msg)
   }
+  // we need the child bindings added to the output first so that logged
+  // objects can take precedence when JSON.parse-ing the resulting log line
+  data = data + this.chindings
   var value
   if (obj) {
     if (obj.stack) {
@@ -138,7 +141,7 @@ function asJson (obj, msg, num) {
       }
     }
   }
-  return data + this.chindings + this.end
+  return data + this.end
 }
 Object.defineProperty(pinoPrototype, 'asJson', {
   enumerable: true,


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index 001fb27..6cd79ff 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -395,3 +395,14 @@ test('handles objects with null prototype', function (t) {
   o.test = 'test'
   instance.info(o)
 })
+
+// https://github.com/pinojs/pino/issues/222
+test('children with same names render in correct order', function (t) {
+  t.plan(1)
+  var root = pino(sink(function (chunk, enc, cb) {
+    t.is(chunk.a, 3, 'last logged object takes precedence')
+    cb()
+  }))
+
+  root.child({a: 1}).child({a: 2}).info({a: 3})
+})
diff --git a/test/browser.test.js b/test/browser.test.js
index f32572e..0edaa28 100644
--- a/test/browser.test.js
+++ b/test/browser.test.js
@@ -234,62 +234,6 @@ test('opts.browser.write obj writes to methods corresponding to level', function
   t.end()
 })
 
-test('opts.browser.asObject/write supports child loggers', function (t) {
-  var instance = pino({
-    browser: {write: function (o) {
-      t.is(o.level, 30)
-      t.is(o.test, 'test')
-      t.is(o.msg, 'msg-test')
-      t.ok(o.time)
-    }}
-  })
-  var child = instance.child({test: 'test'})
-  child.info('msg-test')
-  t.end()
-})
-
-test('opts.browser.asObject/write supports child child loggers', function (t) {
-  var instance = pino({
-    browser: {write: function (o) {
-      t.is(o.level, 30)
-      t.is(o.test, 'test')
-      t.is(o.foo, 'bar')
-      t.is(o.msg, 'msg-test')
-      t.ok(o.time)
-    }}
-  })
-  var child = instance.child({test: 'test'}).child({foo: 'bar'})
-  child.info('msg-test')
-  t.end()
-})
-
-test('opts.browser.asObject/write supports child child child loggers', function (t) {
-  var instance = pino({
-    browser: {write: function (o) {
-      t.is(o.level, 30)
-      t.is(o.test, 'test')
-      t.is(o.foo, 'bar')
-      t.is(o.baz, 'bop')
-      t.is(o.msg, 'msg-test')
-      t.ok(o.time)
-    }}
-  })
-  var child = instance.child({test: 'test'}).child({foo: 'bar'}).child({baz: 'bop'})
-  child.info('msg-test')
-  t.end()
-})
-
-test('opts.browser.asObject defensively mitigates naughty numbers', function (t) {
-  var instance = pino({
-    browser: {asObject: true}
-  })
-  var child = instance.child({test: 'test'})
-  child._childLevel = -10
-  child.info('test')
-  t.pass() // if we reached here, there was no infinite loop, so, .. pass.
-  t.end()
-})
-
 test('opts.browser.write obj falls back to console where a method is not supplied', function (t) {
   t.plan(6)
   var info = console.info