Repository: pinojs/pino
Pull request #528 (2018-10-04 16:23:25)

Makes final warn that is not supported instead of throwing
Fixes https://github.com/pinojs/pino-pretty/issues/37

davidmarkclements: I've read up on the issue - not sure I agree that warning is better than throwing. 

Throwing is the right thing because you shouldn't use pino.final at all with streams 

I'd rather pino-pretty catches the error and then prints a warning itself 

Patch:
diff --git a/lib/levels.js b/lib/levels.js
index 7eb66c4..dc6ba06 100644
--- a/lib/levels.js
+++ b/lib/levels.js
@@ -1,6 +1,6 @@
 'use strict'
 const flatstr = require('flatstr')
-const { lsCacheSym, levelValSym, useLevelLabelsSym, changeLevelNameSym } = require('./symbols')
+const { lsCacheSym, levelValSym, useLevelLabelsSym, changeLevelNameSym, useOnlyCustomLevelsSym } = require('./symbols')
 const { noop, genLog } = require('./tools')
 
 const levels = {
@@ -42,7 +42,11 @@ function genLsCache (instance) {
   return instance
 }
 
-function isStandardLevel (level) {
+function isStandardLevel (level, useOnlyCustomLevels) {
+  if (useOnlyCustomLevels) {
+    return false
+  }
+
   switch (level) {
     case 'fatal':
     case 'error':
@@ -65,13 +69,14 @@ function setLevel (level) {
   if (values[level] === undefined) throw Error('unknown level ' + level)
   const preLevelVal = this[levelValSym]
   const levelVal = this[levelValSym] = values[level]
+  const useOnlyCustomLevelsVal = this[useOnlyCustomLevelsSym]
 
   for (var key in values) {
     if (levelVal > values[key]) {
       this[key] = noop
       continue
     }
-    this[key] = isStandardLevel(key) ? levelMethods[key] : genLog(values[key])
+    this[key] = isStandardLevel(key, useOnlyCustomLevelsVal) ? levelMethods[key] : genLog(values[key])
   }
 
   this.emit(
diff --git a/lib/tools.js b/lib/tools.js
index 069d12a..9398257 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -179,23 +179,47 @@ function getPrettyStream (opts, prettifier, dest) {
 }
 
 function prettifierMetaWrapper (pretty, dest) {
+  var warned = false
   return {
     [needsMetadataGsym]: true,
     lastLevel: 0,
     lastMsg: null,
     lastObj: null,
     lastLogger: null,
-    write (chunk) {
+    flushSync () {
+      if (warned) {
+        return
+      }
+      warned = true
+      dest.write(pretty(Object.assign({
+        level: 40, // warn
+        msg: 'pino.final with prettyPrint does not support flushing',
+        time: Date.now()
+      }, this.chindings())))
+    },
+    chindings () {
       const lastLogger = this.lastLogger
       var chindings = null
 
+      // protection against flushSync being called before logging
+      // anything
+      if (!lastLogger) {
+        return null
+      }
+
       if (lastLogger.hasOwnProperty(parsedChindingsSym)) {
-        chindings = this.lastLogger[parsedChindingsSym]
+        chindings = lastLogger[parsedChindingsSym]
       } else {
-        chindings = JSON.parse('{"v":1' + this.lastLogger[chindingsSym] + '}')
-        this.lastLogger[parsedChindingsSym] = chindings
+        chindings = JSON.parse('{"v":1' + lastLogger[chindingsSym] + '}')
+        lastLogger[parsedChindingsSym] = chindings
       }
 
+      return chindings
+    },
+    write (chunk) {
+      const lastLogger = this.lastLogger
+      const chindings = this.chindings()
+
       var time = this.lastTime
 
       if (time.match(/^\d+/)) {
@@ -220,7 +244,7 @@ function prettifierMetaWrapper (pretty, dest) {
         time
       }, chindings, lastObj, errorProps)
 
-      const serializers = this.lastLogger[serializersSym]
+      const serializers = lastLogger[serializersSym]
       const keys = Object.keys(serializers)
       var key
 
@@ -231,7 +255,7 @@ function prettifierMetaWrapper (pretty, dest) {
         }
       }
 
-      const stringifiers = this.lastLogger[stringifiersSym]
+      const stringifiers = lastLogger[stringifiersSym]
       const redact = stringifiers[redactFmtSym]
 
       const formatted = pretty(typeof redact === 'function' ? redact(obj) : obj)
@@ -287,8 +311,8 @@ function final (logger, handler) {
     throw Error('if supplied, the handler parameter should be a function')
   }
   const stream = logger[streamSym]
-  if (!(stream instanceof SonicBoom)) {
-    throw Error('only compatible with loggers with pino.destination and pino.extreme targets')
+  if (typeof stream.flushSync !== 'function') {
+    throw Error('final requires a stream that has a flushSync method, such as pino.destination and pino.extreme')
   }
 
   const finalLogger = new Proxy(logger, {
diff --git a/package.json b/package.json
index 9c940fe..ee2fe21 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "pino",
-  "version": "5.6.3",
+  "version": "5.6.4",
   "description": "super fast, all natural json logger",
   "main": "pino.js",
   "browser": "./browser.js",


Test patch:
diff --git a/test/custom-levels.test.js b/test/custom-levels.test.js
index f044061..8633638 100644
--- a/test/custom-levels.test.js
+++ b/test/custom-levels.test.js
@@ -31,6 +31,23 @@ test('custom levels does not override default levels', async ({ is }) => {
   is(level, 30)
 })
 
+test('default levels can be redefined using custom levels', async ({ is }) => {
+  const stream = sink()
+  const logger = pino({
+    customLevels: {
+      info: 35,
+      debug: 45
+    },
+    useOnlyCustomLevels: true
+  }, stream)
+
+  is(logger.hasOwnProperty('info'), true)
+
+  logger.info('test')
+  const { level } = await once(stream, 'data')
+  is(level, 35)
+})
+
 test('custom levels overrides default level label if use useOnlyCustomLevels', async ({ is }) => {
   const stream = sink()
   const logger = pino({
diff --git a/test/final.test.js b/test/final.test.js
index 9af04cf..7daeba5 100644
--- a/test/final.test.js
+++ b/test/final.test.js
@@ -27,7 +27,7 @@ test('throws if the supplied handler is not a function', async ({ throws }) => {
 test('throws if not supplied logger with pino.destination or pino.extreme instance', async ({ throws, doesNotThrow }) => {
   throws(() => {
     pino.final(pino(fs.createWriteStream('/dev/null')), () => {})
-  }, Error('only compatible with loggers with pino.destination and pino.extreme'))
+  }, Error('final requires a stream that has a flushSync method, such as pino.destination and pino.extreme'))
 
   doesNotThrow(() => {
     pino.final(pino(pino.destination()), () => {})
diff --git a/test/fixtures/pretty/final-no-log-before.js b/test/fixtures/pretty/final-no-log-before.js
new file mode 100644
index 0000000..7735042
--- /dev/null
+++ b/test/fixtures/pretty/final-no-log-before.js
@@ -0,0 +1,8 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var pino = require(require.resolve('./../../../'))
+var log = pino({ prettyPrint: true })
+process.once('beforeExit', pino.final(log, (_, logger) => {
+  logger.info('beforeExit')
+}))
diff --git a/test/fixtures/pretty/final-return.js b/test/fixtures/pretty/final-return.js
new file mode 100644
index 0000000..d2146ea
--- /dev/null
+++ b/test/fixtures/pretty/final-return.js
@@ -0,0 +1,7 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var pino = require(require.resolve('./../../../'))
+var log = pino({ prettyPrint: true })
+log.info('h')
+pino.final(log).info('after')
diff --git a/test/fixtures/pretty/final.js b/test/fixtures/pretty/final.js
new file mode 100644
index 0000000..1bf07c1
--- /dev/null
+++ b/test/fixtures/pretty/final.js
@@ -0,0 +1,9 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var pino = require(require.resolve('./../../../'))
+var log = pino({ prettyPrint: true })
+log.info('h')
+process.once('beforeExit', pino.final(log, (_, logger) => {
+  logger.info('beforeExit')
+}))
diff --git a/test/pretty.test.js b/test/pretty.test.js
index 8905fc2..ba03d40 100644
--- a/test/pretty.test.js
+++ b/test/pretty.test.js
@@ -202,3 +202,42 @@ test('errors with props', async ({ isNot }) => {
   isNot(actual.match(/errno: 1/), null)
   isNot(actual.match(/.*error-props\.js.*/), null)
 })
+
+test('final works with pretty', async ({ isNot }) => {
+  var actual = ''
+  const child = fork(join(__dirname, 'fixtures', 'pretty', 'final.js'), { silent: true })
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+  await once(child, 'close')
+  isNot(actual.match(/WARN \(123456 on abcdefghijklmnopqr\): pino.final with prettyPrint does not support flushing/), null)
+  isNot(actual.match(/INFO \(123456 on abcdefghijklmnopqr\): beforeExit/), null)
+})
+
+test('final works when returning a logger', async ({ isNot }) => {
+  var actual = ''
+  const child = fork(join(__dirname, 'fixtures', 'pretty', 'final-return.js'), { silent: true })
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+  await once(child, 'close')
+  isNot(actual.match(/WARN \(123456 on abcdefghijklmnopqr\): pino.final with prettyPrint does not support flushing/), null)
+  isNot(actual.match(/INFO \(123456 on abcdefghijklmnopqr\): after/), null)
+})
+
+test('final works without prior logging', async ({ isNot }) => {
+  var actual = ''
+  const child = fork(join(__dirname, 'fixtures', 'pretty', 'final-no-log-before.js'), { silent: true })
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+  await once(child, 'close')
+  isNot(actual.match(/WARN: pino.final with prettyPrint does not support flushing/), null)
+  isNot(actual.match(/INFO \(123456 on abcdefghijklmnopqr\): beforeExit/), null)
+})