Repository: pinojs/pino
Pull request #597 (2019-02-05 13:59:36)

Fix bug Global serializer not invoked for strings when `base: null`

yellowbrickc: I run the both benchmarks a few times and the result was always different, even the measurements for bunyan and co. In the last run some numbers for pino are higher, some are lower.
I'm attaching the 2 text files here. 
[bench_master.txt](https://github.com/pinojs/pino/files/2836042/bench_master.txt)
[bench_issue_479.txt](https://github.com/pinojs/pino/files/2836044/bench_issue_479.txt)

mcollina: Numbers should be stable, maybe you had something else running on your computer? Docker, Chrome, Slack could all be responsible :/.
davidmarkclements: .. ok I'm just thinking this through.. can you please correct verify this assumption:

we're making a change to the metadata API (by adding a `msg` property) to solve the global serializer not being invoked when base is null?

@yellowbrickc can you also add comparison benchmarks – as @mcollina says try making sure you have minimum background processes. Also, choose benchmarks that would hit this path and feel free to comment out the benchmarks for other loggers (which also might help with clearer numbers). Even with background processes disabled, they'll always vary slightly, but you're looking for within ~1-2%
yellowbrickc: I run the file /internal/just-pino.bench.js twice per branch and the numbers are reliable now. They look good I think but it is your call of course
[bench_issue.txt](https://github.com/pinojs/pino/files/2837786/bench_issue.txt)
[bench_master.txt](https://github.com/pinojs/pino/files/2837789/bench_master.txt)



yellowbrickc: > we're making a change to the metadata API (by adding a `msg` property) to solve the global serializer not being invoked when base is null?

The only change regarding the metadata (the tests prove this) is that `this.lastObj` gets the property `msg`. The global serializer is applied to this object (before it became the `lastObject` ) This way it is ensured that the same logic is applied to the `msg` as to all the other properties to be logged.

But you are right, the connection to `base=null` is not visible. I debugged now again and found the culprit: https://github.com/pinojs/pino/blob/master/pino.js#L88
The serializer is called in tools.js in the method asChindings https://github.com/pinojs/pino/blob/master/lib/tools.js#L148 

I think there is no connection between the `base = null` and the missing call to the serializer, the reproduction through console.log has led to false conclusion. Fact is, the prop msg was logged differently from the rest and this is the bug.


Patch:
diff --git a/README.md b/README.md
index cefc94f..1452aad 100644
--- a/README.md
+++ b/README.md
@@ -1,6 +1,6 @@
 ![banner](pino-banner.png)
 
-# pino&nbsp;&nbsp;[![Build Status](https://travis-ci.org/pinojs/pino.svg?branch=master)](https://travis-ci.org/pinojs/pino)&nbsp;[![Coverage Status](https://coveralls.io/repos/github/pinojs/pino/badge.svg?branch=master)](https://coveralls.io/github/pinojs/pino?branch=master) [![js-standard-style](https://img.shields.io/badge/code%20style-standard-brightgreen.svg?style=flat)](http://standardjs.com/) [![TypeScript definitions on DefinitelyTyped](http://definitelytyped.org/badges/standard.svg)](http://definitelytyped.org)
+# pino&nbsp;&nbsp;[![Build Status](https://travis-ci.org/pinojs/pino.svg?branch=master)](https://travis-ci.org/pinojs/pino)&nbsp;[![Coverage Status](https://coveralls.io/repos/github/pinojs/pino/badge.svg?branch=master)](https://coveralls.io/github/pinojs/pino?branch=master) [![js-standard-style](https://img.shields.io/badge/code%20style-standard-brightgreen.svg?style=flat)](http://standardjs.com/) [![TypeScript definitions on DefinitelyTyped](https://definitelytyped.org/badges/standard.svg)](https://definitelytyped.org)
 
 [Very low overhead](#low-overhead) Node.js logger, inspired by Bunyan.
 
diff --git a/browser.js b/browser.js
index a6384c6..22ed05a 100644
--- a/browser.js
+++ b/browser.js
@@ -6,6 +6,10 @@ module.exports = pino
 
 var _console = global.console || {}
 var stdSerializers = {
+  mapHttpRequest: mock,
+  mapHttpResponse: mock,
+  wrapRequestSerializer: passthrough,
+  wrapResponseSerializer: passthrough,
   req: mock,
   res: mock,
   err: asErrValue
@@ -157,6 +161,7 @@ pino.levels = {
 }
 
 pino.stdSerializers = stdSerializers
+pino.symbols = require('./lib/symbols')
 
 function set (opts, logger, level, fallback) {
   var proto = Object.getPrototypeOf(logger)
@@ -296,4 +301,5 @@ function asErrValue (err) {
 }
 
 function mock () { return {} }
+function passthrough (a) { return a }
 function noop () {}
diff --git a/docs/api.md b/docs/api.md
index 38d8391..0a76634 100644
--- a/docs/api.md
+++ b/docs/api.md
@@ -521,7 +521,7 @@ This is an asynchronous, fire and forget, operation.
 The use case is primarily for Extreme mode logging, which may hold up to
 4KiB of logs. The `logger.flush` method can be used to flush the logs
 on an long interval, say ten seconds. Such a strategy can provide an
-optimium balanace between extremely efficient logging at high demand periods
+optimium balance between extremely efficient logging at high demand periods
 and safer logging at low demand periods.
 
 * See [`pino.extreme`](#pino-extreme)
diff --git a/docs/ecosystem.md b/docs/ecosystem.md
index b12324b..780dd79 100644
--- a/docs/ecosystem.md
+++ b/docs/ecosystem.md
@@ -67,4 +67,5 @@ the logger for the [Rill framework](https://rill.site/).
 MongoDB and many [others](https://www.fluentd.org/dataoutputs) via Fluentd.
 + [`pino-pretty-min`](https://github.com/unjello/pino-pretty-min): a minimal
 prettifier inspired by the [logrus](https://github.com/sirupsen/logrus) logger.
++ [`cls-proxify`](https://github.com/keenondrums/cls-proxify): integration of pino and [CLS](https://github.com/jeff-lewis/cls-hooked). Useful for creating dynamically configured child loggers (e.g. with added trace ID) for each request. 
 
diff --git a/lib/redaction.js b/lib/redaction.js
index 6c075e8..5e7fd92 100644
--- a/lib/redaction.js
+++ b/lib/redaction.js
@@ -72,8 +72,10 @@ function redaction (opts, serialize) {
   const result = {
     [redactFmtSym]: fastRedact({ paths, censor, serialize, strict })
   }
-  const serializedCensor = serialize(censor)
-  const topCensor = () => serializedCensor
+
+  const topCensor = (...args) =>
+    typeof censor === 'function' ? serialize(censor(...args)) : serialize(censor)
+
   return [...Object.keys(shape), ...Object.getOwnPropertySymbols(shape)].reduce((o, k) => {
     // top level key:
     if (shape[k] === null) o[k] = topCensor
diff --git a/lib/symbols.js b/lib/symbols.js
index ea9328c..503f432 100644
--- a/lib/symbols.js
+++ b/lib/symbols.js
@@ -21,7 +21,7 @@ const stringifySym = Symbol('pino.stringify')
 const stringifiersSym = Symbol('pino.stringifiers')
 const endSym = Symbol('pino.end')
 const formatOptsSym = Symbol('pino.formatOpts')
-const messageKeyStringSym = Symbol('pino.messageKeyString')
+const messageKeySym = Symbol('pino.messageKey')
 
 const wildcardFirstSym = Symbol('pino.wildcardFirst')
 
@@ -49,7 +49,7 @@ module.exports = {
   stringifiersSym,
   endSym,
   formatOptsSym,
-  messageKeyStringSym,
+  messageKeySym,
   wildcardFirstSym,
   changeLevelNameSym,
   wildcardGsym,
diff --git a/lib/tools.js b/lib/tools.js
index 92d44bc..95a247e 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -9,7 +9,7 @@ const {
   chindingsSym,
   parsedChindingsSym,
   writeSym,
-  messageKeyStringSym,
+  messageKeySym,
   serializersSym,
   formatOptsSym,
   endSym,
@@ -68,69 +68,73 @@ function asString (str) {
 }
 
 function asJson (obj, msg, num, time) {
-  // to catch both null and undefined
-  const hasObj = obj !== undefined && obj !== null
-  const objError = hasObj && obj instanceof Error
-  msg = !msg && objError === true ? obj.message : msg || undefined
+  const objError = obj instanceof Error
+  const messageKey = this[messageKeySym]
+  if (obj === undefined || obj === null) obj = {}
+  if (msg) {
+    obj[messageKey] = msg
+  } else if (objError === true) {
+    obj[messageKey] = obj.message
+  }
   const stringify = this[stringifySym]
   const stringifiers = this[stringifiersSym]
   const end = this[endSym]
-  const messageKeyString = this[messageKeyStringSym]
   const chindings = this[chindingsSym]
   const serializers = this[serializersSym]
   var data = this[lsCacheSym][num] + time
-  if (msg !== undefined) {
-    data += messageKeyString + asString('' + msg)
-  }
+
   // we need the child bindings added to the output first so instance logged
   // objects can take precedence when JSON.parse-ing the resulting log line
   data = data + chindings
+
   var value
-  if (hasObj === true) {
-    var notHasOwnProperty = obj.hasOwnProperty === undefined
-    if (objError === true) {
-      data += ',"type":"Error"'
-      if (obj.stack !== undefined) {
-        data += ',"stack":' + stringify(obj.stack)
-      }
-    }
-    // if global serializer is set, call it first
-    if (serializers[wildcardGsym]) {
-      obj = serializers[wildcardGsym](obj)
+  var notHasOwnProperty = obj.hasOwnProperty === undefined
+  if (objError === true) {
+    data += ',"type":"Error"'
+    if (obj.stack !== undefined) {
+      data += ',"stack":' + stringify(obj.stack)
     }
-    const wildcardStringifier = stringifiers[wildcardFirstSym]
-    for (var key in obj) {
-      value = obj[key]
-      if ((notHasOwnProperty || obj.hasOwnProperty(key)) && value !== undefined) {
-        value = serializers[key] ? serializers[key](value) : value
-
-        const stringifier = stringifiers[key] || wildcardStringifier
-
-        switch (typeof value) {
-          case 'undefined':
-          case 'function':
-            continue
-          case 'number':
-            /* eslint no-fallthrough: "off" */
-            if (Number.isFinite(value) === false) {
-              value = null
-            }
-            // this case explicity falls through to the next one
-          case 'boolean':
-            if (stringifier) value = stringifier(value)
-            data += ',"' + key + '":' + value
-            continue
-          case 'string':
-            value = (stringifier || asString)(value)
-            break
-          default:
-            value = (stringifier || stringify)(value)
-        }
-        if (value === undefined) continue
-        data += ',"' + key + '":' + value
+  }
+  if (serializers[wildcardGsym]) {
+    obj = serializers[wildcardGsym](obj)
+  }
+  const wildcardStringifier = stringifiers[wildcardFirstSym]
+  for (var key in obj) {
+    value = obj[key]
+    if ((notHasOwnProperty || obj.hasOwnProperty(key)) && value !== undefined) {
+      value = serializers[key] ? serializers[key](value) : value
+
+      const stringifier = stringifiers[key] || wildcardStringifier
+
+      switch (typeof value) {
+        case 'undefined':
+        case 'function':
+          continue
+        case 'number':
+          /* eslint no-fallthrough: "off" */
+          if (Number.isFinite(value) === false) {
+            value = null
+          }
+        // this case explicity falls through to the next one
+        case 'boolean':
+          if (stringifier) value = stringifier(value)
+          data += ',"' + key + '":' + value
+          continue
+        case 'string':
+          value = (stringifier || asString)(value)
+          break
+        default:
+          value = (stringifier || stringify)(value)
       }
+      if (value === undefined) continue
+      data += ',"' + key + '":' + value
     }
   }
+
+  if (msg !== undefined) {
+    data += messageKeyString + asString('' + msg)
+  }
+
   return data + end
 }
 
diff --git a/package.json b/package.json
index 5f4674c..a04b442 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "pino",
-  "version": "5.11.1",
+  "version": "5.11.3",
   "description": "super fast, all natural json logger",
   "main": "pino.js",
   "browser": "./browser.js",
@@ -18,9 +18,9 @@
   "scripts": {
     "docs": "docsify serve",
     "browser-test": "airtap --local 8080 test/browser*test.js",
-    "test": "standard | snazzy && NODE_OPTIONS='--no-warnings -r qodaa' tap -j 4 --no-cov test/*test.js",
-    "ci": "standard | snazzy && TAP_TIMEOUT=480000 NODE_OPTIONS='--no-warnings -r qodaa' tap -j 4 --100 test/*test.js",
-    "cov-ui": "NODE_OPTIONS='--no-warnings -r qodaa' tap -j 4 --coverage-report=html test/*test.js",
+    "test": "standard | snazzy && NODE_OPTIONS='--no-warnings -r qodaa' tap --no-esm -j 4 --no-cov test/*test.js",
+    "ci": "standard | snazzy && TAP_TIMEOUT=480000 NODE_OPTIONS='--no-warnings -r qodaa' tap --no-esm -j 4 --100 test/*test.js",
+    "cov-ui": "NODE_OPTIONS='--no-warnings -r qodaa' tap --no-esm -j 4 --coverage-report=html test/*test.js",
     "bench": "node benchmarks/utils/runbench all",
     "bench-basic": "node benchmarks/utils/runbench basic",
     "bench-object": "node benchmarks/utils/runbench object",
@@ -58,37 +58,37 @@
   },
   "homepage": "http://getpino.io",
   "devDependencies": {
-    "airtap": "0.1.0",
+    "airtap": "2.0.2",
     "benchmark": "^2.1.4",
     "bole": "^3.0.2",
     "bunyan": "^1.8.12",
     "docsify-cli": "^4.2.1",
     "execa": "^1.0.0",
     "fastbench": "^1.0.1",
-    "flush-write-stream": "^1.0.3",
+    "flush-write-stream": "^2.0.0",
     "fresh-require": "^1.0.3",
-    "log": "^3.0.0",
+    "log": "^5.0.0",
     "loglevel": "^1.6.1",
     "pino-pretty": "^2.4.0",
     "pre-commit": "^1.2.2",
     "proxyquire": "^2.1.0",
+    "pump": "^3.0.0",
     "qodaa": "^1.0.1",
     "snazzy": "^8.0.0",
-    "split2": "^3.0.0",
+    "split2": "^3.1.1",
     "standard": "^12.0.1",
     "steed": "^1.1.3",
-    "tap": "^12.1.0",
-    "tape": "^4.9.0",
-    "through2": "^3.0.0",
-    "winston": "^3.1.0",
-    "pump": "^3.0.0"
+    "tap": "^12.6.0",
+    "tape": "^4.10.1",
+    "through2": "^3.0.1",
+    "winston": "^3.2.1"
   },
   "dependencies": {
-    "fast-redact": "^1.4.2",
+    "fast-redact": "^1.4.4",
     "fast-safe-stringify": "^2.0.6",
     "flatstr": "^1.0.9",
     "pino-std-serializers": "^2.3.0",
-    "quick-format-unescaped": "^3.0.0",
-    "sonic-boom": "^0.7.1"
+    "quick-format-unescaped": "^3.0.2",
+    "sonic-boom": "^0.7.3"
   }
 }
diff --git a/pino.js b/pino.js
index 072d1e8..f9dd378 100644
--- a/pino.js
+++ b/pino.js
@@ -25,7 +25,7 @@ const {
   setLevelSym,
   endSym,
   formatOptsSym,
-  messageKeyStringSym,
+  messageKeySym,
   useLevelLabelsSym,
   changeLevelNameSym,
   useOnlyCustomLevelsSym
@@ -77,7 +77,6 @@ function pino (...args) {
   const formatOpts = redact
     ? { stringify: stringifiers[redactFmtSym] }
     : { stringify }
-  const messageKeyString = `,"${messageKey}":`
   const end = ',"v":' + LOG_VERSION + '}' + (crlf ? '\r\n' : '\n')
   const coreChindings = asChindings.bind(null, {
     [chindingsSym]: '',
@@ -106,7 +105,7 @@ function pino (...args) {
     [stringifiersSym]: stringifiers,
     [endSym]: end,
     [formatOptsSym]: formatOpts,
-    [messageKeyStringSym]: messageKeyString,
+    [messageKeySym]: messageKey,
     [serializersSym]: serializers,
     [chindingsSym]: chindings
   }


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index f164f21..7f06bd0 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -76,6 +76,24 @@ function levelTest (name, level) {
     })
   })
 
+  test(`overriding object key by string at level ${name}`, async ({ is, same }) => {
+    const stream = sink()
+    const instance = pino(stream)
+    instance.level = name
+    instance[name]({ hello: 'world', msg: 'object' }, 'string')
+    const result = await once(stream, 'data')
+    is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
+    delete result.time
+    same(result, {
+      pid: pid,
+      hostname: hostname,
+      level: level,
+      msg: 'string',
+      hello: 'world',
+      v: 1
+    })
+  })
+
   test(`formatting logs as ${name}`, async ({ is }) => {
     const stream = sink()
     const instance = pino(stream)
@@ -261,6 +279,28 @@ test('set the base to null', async ({ is, same }) => {
   })
 })
 
+test('set the base to null and use a serializer', async ({ is, same }) => {
+  const stream = sink()
+  const instance = pino({
+    base: null,
+    serializers: {
+      [Symbol.for('pino.*')]: (input) => {
+        return Object.assign({}, input, { additionalMessage: 'using pino' })
+      }
+    }
+  }, stream)
+  instance.fatal('this is fatal too')
+  const result = await once(stream, 'data')
+  is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
+  delete result.time
+  same(result, {
+    level: 60,
+    msg: 'this is fatal too',
+    additionalMessage: 'using pino',
+    v: 1
+  })
+})
+
 test('throw if creating child without bindings', async ({ throws }) => {
   const stream = sink()
   const instance = pino(stream)
diff --git a/test/browser.test.js b/test/browser.test.js
index 0218448..cdbfff9 100644
--- a/test/browser.test.js
+++ b/test/browser.test.js
@@ -1,6 +1,8 @@
 'use strict'
 const test = require('tape')
 const fresh = require('fresh-require')
+const pinoStdSerializers = require('pino-std-serializers')
+const pinoSymbols = require('../lib/symbols')
 const pino = require('../browser')
 
 levelTest('fatal')
@@ -101,22 +103,36 @@ test('exposes LOG_VERSION', ({ end, is }) => {
 
 test('exposes faux stdSerializers', ({ end, ok, same }) => {
   ok(pino.stdSerializers)
-  ok(pino.stdSerializers.req)
-  ok(pino.stdSerializers.res)
-  ok(pino.stdSerializers.err)
+  // make sure faux stdSerializers match pino-std-serializers
+  for (let serializer in pinoStdSerializers) {
+    ok(pino.stdSerializers[serializer], `pino.stdSerializers.${serializer}`)
+  }
+  // confirm faux methods return empty objects
   same(pino.stdSerializers.req(), {})
+  same(pino.stdSerializers.mapHttpRequest(), {})
+  same(pino.stdSerializers.mapHttpResponse(), {})
   same(pino.stdSerializers.res(), {})
-
+  // confirm wrapping function is a passthrough
+  const noChange = { foo: 'bar', fuz: 42 }
+  same(pino.stdSerializers.wrapRequestSerializer(noChange), noChange)
+  same(pino.stdSerializers.wrapResponseSerializer(noChange), noChange)
   end()
 })
 
 test('exposes err stdSerializer', ({ end, ok }) => {
-  ok(pino.stdSerializers)
-  ok(pino.stdSerializers.req)
-  ok(pino.stdSerializers.res)
   ok(pino.stdSerializers.err)
   ok(pino.stdSerializers.err(Error()))
+  end()
+})
 
+test('exposes real symbols', ({ end, ok, same }) => {
+  ok(pino.symbols)
+  // confirm every symbol is present
+  for (let symbol in pinoSymbols) {
+    ok(pino.symbols[symbol], `pino.symbols.${symbol}`)
+  }
+  // confirm real symbols are used
+  same(pino.symbols, pinoSymbols)
   end()
 })
 
diff --git a/test/metadata.test.js b/test/metadata.test.js
index 0ceee2b..729e733 100644
--- a/test/metadata.test.js
+++ b/test/metadata.test.js
@@ -16,7 +16,7 @@ test('metadata works', async ({ ok, same, is }) => {
       is(30, this.lastLevel)
       is('a msg', this.lastMsg)
       ok(Number(this.lastTime) >= now)
-      same({ hello: 'world' }, this.lastObj)
+      same(this.lastObj, { hello: 'world', msg: 'a msg' })
       const result = JSON.parse(chunk)
       ok(new Date(result.time) <= new Date(), 'time is greater than Date.now()')
       delete result.time
@@ -41,7 +41,7 @@ test('child loggers works', async ({ ok, same, is }) => {
       is(child, this.lastLogger)
       is(30, this.lastLevel)
       is('a msg', this.lastMsg)
-      same({ from: 'child' }, this.lastObj)
+      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()')
       delete result.time
diff --git a/test/redact.test.js b/test/redact.test.js
index 8856dcf..26db3ac 100644
--- a/test/redact.test.js
+++ b/test/redact.test.js
@@ -481,6 +481,32 @@ test('redact – supports top level wildcard', async ({ is }) => {
   is(req, '[Redacted]')
 })
 
+test('redact – supports top level wildcard with a censor function', async ({ is }) => {
+  const stream = sink()
+  const instance = pino({
+    redact: {
+      paths: ['*'],
+      censor: () => '[Redacted]'
+    }
+  }, stream)
+  instance.info({
+    req: {
+      id: 7915,
+      method: 'GET',
+      url: '/',
+      headers: {
+        host: 'localhost:3000',
+        connection: 'keep-alive',
+        cookie: 'SESSID=298zf09hf012fh2; csrftoken=u32t4o3tb3gg43; _gat=1;'
+      },
+      remoteAddress: '::ffff:127.0.0.1',
+      remotePort: 58022
+    }
+  })
+  const { req } = await once(stream, 'data')
+  is(req, '[Redacted]')
+})
+
 test('redact – supports top level wildcard and leading wildcard', async ({ is }) => {
   const stream = sink()
   const instance = pino({ redact: ['*', '*.req'] }, stream)