Merge f416818 into d5a380d

benchmarks/basic.bench.js

@@ -8,11 +8,11 @@ const winston = require('winston')
 const fs = require('fs')
 const dest = fs.createWriteStream('/dev/null')
 const loglevel = require('./utils/wrap-log-level')(dest)
-const plog = pino(dest)
+const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
 const plogExtreme = require('../')(pino.extreme('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogDest = require('../')(pino.destination('/dev/null'))
+const plog = require('../')(pino.destination('/dev/null'))
 
 process.env.DEBUG = 'dlog'
 const debug = require('debug')
@@ -78,15 +78,15 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoDestination (cb) {
+  function benchPinoExtreme (cb) {
     for (var i = 0; i < max; i++) {
-      plogDest.info('hello world')
+      plogExtreme.info('hello world')
     }
     setImmediate(cb)
   },
-  function benchPinoExtreme (cb) {
+  function benchPinoNodeStream (cb) {
     for (var i = 0; i < max; i++) {
-      plogExtreme.info('hello world')
+      plogNodeStream.info('hello world')
     }
     setImmediate(cb)
   }

benchmarks/child-child.bench.js

@@ -5,7 +5,9 @@ const pino = require('../')
 const bunyan = require('bunyan')
 const fs = require('fs')
 const dest = fs.createWriteStream('/dev/null')
-const plog = pino(dest).child({ a: 'property' }).child({sub: 'child'})
+const plog = pino(pino.destination('/dev/null')).child({ a: 'property' }).child({sub: 'child'})
+delete require.cache[require.resolve('../')]
+const plogNodeStream = pino(dest).child({ a: 'property' }).child({sub: 'child'})
 delete require.cache[require.resolve('../')]
 const plogExtreme = require('../')(pino.extreme('/dev/null'))
   .child({ a: 'property' })
@@ -38,6 +40,12 @@ const run = bench([
       plogExtreme.info({ hello: 'world' })
     }
     setImmediate(cb)
+  },
+  function benchPinoNodeStreamChildChild (cb) {
+    for (var i = 0; i < max; i++) {
+      plogNodeStream.info({ hello: 'world' })
+    }
+    setImmediate(cb)
   }
 ], 10000)
 

benchmarks/child.bench.js

@@ -6,7 +6,9 @@ const bunyan = require('bunyan')
 const bole = require('bole')('bench')('child')
 const fs = require('fs')
 const dest = fs.createWriteStream('/dev/null')
-const plog = pino(dest).child({ a: 'property' })
+const plog = pino(pino.destination('/dev/null')).child({ a: 'property' })
+delete require.cache[require.resolve('../')]
+const plogNodeStream = pino(dest).child({ a: 'property' })
 delete require.cache[require.resolve('../')]
 const plogExtreme = require('../')(pino.extreme('/dev/null')).child({ a: 'property' })
 
@@ -48,6 +50,12 @@ const run = bench([
       plogExtreme.info({ hello: 'world' })
     }
     setImmediate(cb)
+  },
+  function benchPinoNodeStreamChild (cb) {
+    for (var i = 0; i < max; i++) {
+      plogNodeStream.info({ hello: 'world' })
+    }
+    setImmediate(cb)
   }
 ], 10000)
 

benchmarks/deep-object.bench.js

@@ -7,13 +7,11 @@ const bole = require('bole')('bench')
 const winston = require('winston')
 const fs = require('fs')
 const dest = fs.createWriteStream('/dev/null')
-const plog = pino(dest)
+const plog = pino(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogExtreme = require('../')(pino.extreme('/dev/null'))
-delete require.cache[require.resolve('../')]
-const plogUnsafe = require('../')({safe: false}, dest)
+const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
-const plogUnsafeExtreme = require('../')({safe: false}, pino.extreme('/dev/null'))
+const plogExtreme = require('../')(pino.extreme('/dev/null'))
 
 const loglevel = require('./utils/wrap-log-level')(dest)
 
@@ -69,30 +67,24 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoDeepObj (cb) {
-    for (var i = 0; i < max; i++) {
-      plog.info(deep)
-    }
-    setImmediate(cb)
-  },
-  function benchPinoUnsafeDeepObj (cb) {
+  function benchPinoExtremeDeepObj (cb) {
     for (var i = 0; i < max; i++) {
-      plogUnsafe.info(deep)
+      plogExtreme.info(deep)
     }
     setImmediate(cb)
   },
-  function benchPinoExtremeDeepObj (cb) {
+  function benchPinoNodeStreamDeepObj (cb) {
     for (var i = 0; i < max; i++) {
-      plogExtreme.info(deep)
+      plogNodeStream.info(deep)
     }
     setImmediate(cb)
   },
-  function benchPinoUnsafeExtremeDeepObj (cb) {
+  function benchPinoDeepObj (cb) {
     for (var i = 0; i < max; i++) {
-      plogUnsafeExtreme.info(deep)
+      plog.info(deep)
     }
     setImmediate(cb)
   }
-], 10000)
+], 1000)
 
 run(run)

benchmarks/object.bench.js

@@ -8,13 +8,11 @@ const winston = require('winston')
 const fs = require('fs')
 const dest = fs.createWriteStream('/dev/null')
 const loglevel = require('./utils/wrap-log-level')(dest)
-const plog = pino(dest)
+const plog = pino(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogExtreme = require('../')(pino.extreme('/dev/null'))
-delete require.cache[require.resolve('../')]
-const plogUnsafe = require('../')({safe: false}, dest)
+const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
-const plogUnsafeExtreme = require('../')({safe: false}, pino.extreme('/dev/null'))
+const plogExtreme = require('../')(pino.extreme('/dev/null'))
 const blog = bunyan.createLogger({
   name: 'myapp',
   streams: [{
@@ -55,7 +53,7 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchLogLevelObject (cb) {
+  function benchLogLevelObj (cb) {
     for (var i = 0; i < max; i++) {
       loglevel.info({ hello: 'world' })
     }
@@ -67,21 +65,15 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoUnsafeObj (cb) {
-    for (var i = 0; i < max; i++) {
-      plogUnsafe.info({ hello: 'world' })
-    }
-    setImmediate(cb)
-  },
   function benchPinoExtremeObj (cb) {
     for (var i = 0; i < max; i++) {
       plogExtreme.info({ hello: 'world' })
     }
     setImmediate(cb)
   },
-  function benchPinoUnsafeExtremeObj (cb) {
+  function benchPinoNodeStreamObj (cb) {
     for (var i = 0; i < max; i++) {
-      plogUnsafeExtreme.info({ hello: 'world' })
+      plogNodeStream.info({ hello: 'world' })
     }
     setImmediate(cb)
   }

lib/redaction.js

@@ -1,7 +1,7 @@
 'use strict'
 
 const fastRedact = require('fast-redact')
-const { redactFmtSym } = require('./symbols')
+const { redactSym } = require('./symbols')
 const { rx, validator } = fastRedact
 
 const validate = validator({
@@ -30,11 +30,12 @@ function redaction (opts, serialize) {
     return o
   }, {})
 
-  // the redactor assigned to the format symbol key
+  // the redactor assigned to the redactSym key
   // provides top level redaction for instances where
-  // an object is interpolated into the msg string
+  // an object is interpolated into the msg string or
+  // as a fast-path for objects with serializer keys
   const result = {
-    [redactFmtSym]: fastRedact({paths, censor, serialize})
+    [redactSym]: fastRedact({paths, censor, serialize})
   }
   const serializedCensor = serialize(censor)
   const topCensor = () => serializedCensor

lib/symbols.js

@@ -11,7 +11,7 @@ const parsedChindingsSym = Symbol('pino.parsedChindings')
 const asJsonSym = Symbol('pino.asJson')
 const writeSym = Symbol('pino.write')
 const serializersSym = Symbol('pino.serializers')
-const redactFmtSym = Symbol('pino.redactFmt')
+const redactSym = Symbol('pino.redact')
 
 const timeSym = Symbol('pino.time')
 const streamSym = Symbol('pino.stream')
@@ -34,7 +34,7 @@ module.exports = {
   asJsonSym,
   writeSym,
   serializersSym,
-  redactFmtSym,
+  redactSym,
   timeSym,
   streamSym,
   stringifySym,

lib/tools.js

@@ -1,5 +1,5 @@
 'use strict'
-
+const stringify = require('fast-safe-stringify')
 const format = require('quick-format-unescaped')
 const { mapHttpRequest, mapHttpResponse } = require('pino-std-serializers')
 const SonicBoom = require('sonic-boom')
@@ -16,7 +16,8 @@ const {
   stringifySym,
   needsMetadataGsym,
   wildcardGsym,
-  streamSym
+  streamSym,
+  redactSym
 } = require('./symbols')
 
 function noop () {}
@@ -82,26 +83,41 @@ function asJson (obj, msg, num, time) {
   // 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
+
+  if (hasObj === false) return data + end
+
+  const notHasOwnProperty = obj.hasOwnProperty === undefined
+
+  if (objError === true) {
+    data += ',"type":"Error","stack":' + stringify(obj.stack)
+  }
+
+  // if global serializer is set, call it first
+  if (serializers[wildcardGsym]) {
+    obj = serializers[wildcardGsym](obj)
+  }
+
+  var hasSerializableKeys = false
+  for (var szKey in serializers) {
+    if (szKey in obj) hasSerializableKeys = true
+  }
+  if (hasSerializableKeys === false) {
+    const str = (stringifiers[redactSym] || stringify)(obj)
+    const len = str.length
+    return len === 2 ? data + end : data + ',' + str.substr(1, len - 2) + end
+  }
+
   var value
-  if (hasObj === true) {
-    var notHasOwnProperty = obj.hasOwnProperty === undefined
-    if (objError === true) {
-      data += ',"type":"Error","stack":' + stringify(obj.stack)
-    }
-    // if global serializer is set, call it first
-    if (serializers[wildcardGsym]) {
-      obj = serializers[wildcardGsym](obj)
-    }
-    for (var key in obj) {
-      value = obj[key]
-      if ((notHasOwnProperty || obj.hasOwnProperty(key)) && value !== undefined) {
-        value = (stringifiers[key] || stringify)(serializers[key] ? serializers[key](value) : value)
-        if (value !== undefined) {
-          data += ',"' + key + '":' + value
-        }
+  for (var key in obj) {
+    value = obj[key]
+    if ((notHasOwnProperty || obj.hasOwnProperty(key)) && value !== undefined) {
+      value = (stringifiers[key] || stringify)(serializers[key] ? serializers[key](value) : value)
+      if (value !== undefined) {
+        data += ',"' + key + '":' + value
       }
     }
   }
+
   return data + end
 }
 
@@ -237,12 +253,21 @@ function final (logger, handler) {
   }
 }
 
+function stringifySafe (obj, replacer, spacer) {
+  try {
+    return JSON.stringify(obj, replacer, spacer)
+  } catch (e) {
+    return stringify(obj, replacer, spacer)
+  }
+}
+
 module.exports = {
   noop,
   getPrettyStream,
   asChindings,
   asJson,
   genLog,
+  stringifySafe,
   createArgsNormalizer,
   final
 }

pino.js

@@ -1,18 +1,17 @@
 'use strict'
 const os = require('os')
-const stringifySafe = require('fast-safe-stringify')
 const serializers = require('pino-std-serializers')
 const SonicBoom = require('sonic-boom')
 const redaction = require('./lib/redaction')
 const time = require('./lib/time')
 const proto = require('./lib/proto')
 const symbols = require('./lib/symbols')
 const { mappings, genLsCache, assertNoLevelCollisions } = require('./lib/levels')
-const { createArgsNormalizer, asChindings, final } = require('./lib/tools')
+const { createArgsNormalizer, asChindings, final, stringifySafe } = require('./lib/tools')
 const { version, LOG_VERSION } = require('./lib/meta')
 const {
   chindingsSym,
-  redactFmtSym,
+  redactSym,
   serializersSym,
   timeSym,
   streamSym,
@@ -63,7 +62,7 @@ function pino (...args) {
   const stringify = safe ? stringifySafe : JSON.stringify
   const stringifiers = redact ? redaction(redact, stringify) : {}
   const formatOpts = redact
-    ? {stringify: stringifiers[redactFmtSym]}
+    ? {stringify: stringifiers[redactSym]}
     : { stringify }
   const messageKeyString = `,"${messageKey}":`
   const end = ',"v":' + LOG_VERSION + '}' + (crlf ? '\r\n' : '\n')

test/basic.test.js

@@ -446,12 +446,14 @@ test('children with same names render in correct order', async ({is}) => {
 })
 
 // https://github.com/pinojs/pino/pull/251 - use this.stringify
-test('when safe is true it should ONLY use `fast-safe-stringify`', async ({is}) => {
+test('when safe is true it should ONLY use stringifySafe', async ({is}) => {
   var isFastSafeStringifyCalled = false
   const mockedPino = proxyquire('../', {
-    'fast-safe-stringify' () {
-      isFastSafeStringifyCalled = true
-      return '{ "hello": "world" }'
+    './lib/tools.js': {
+      stringifySafe () {
+        isFastSafeStringifyCalled = true
+        return '{ "hello": "world" }'
+      }
     }
   })
   const instance = mockedPino({ safe: true }, sink())