Merge pull request #566 from pinojs/make-destination-sync

Make pino.destination sync

docs/api.md

@@ -662,9 +662,6 @@ By default, `pino.destination` will use `process.stdout.fd` (1) as the file desc
 A `pino.destination` instance can also be used to reopen closed files
 (for example, for some log rotation scenarios), see [Reopening log files](/docs/help.md#reopening).
 
-On AWS Lambda we recommend to call `destination.flushSync()` at the end
-of each function execution to avoid losing data.
-
 * See [`destination` parameter](#destination)
 * See [`sonic-boom` ⇗](https://github.com/mcollina/sonic-boom)
 * See [Reopening log files](/docs/help.md#reopening)
@@ -707,13 +704,14 @@ or create an exit listener function.
 
 The `finalLogger` is a specialist logger that synchronously flushes
 on every write. This is important to guarantee final log writes,
-both when using `pino.destination` or `pino.extreme` targets.
+both when using `pino.extreme` target.
 
 Since final log writes cannot be guaranteed with normal Node.js streams,
 if the `destination` parameter of the `logger` supplied to `pino.final`
-is a Node.js stream `pino.final` will throw. It's highly recommended
-for both performance and safety to use `pino.destination`/`pino.extreme`
-destinations.
+is a Node.js stream `pino.final` will throw.
+
+The use of `pino.final` with `pino.destination` is not needed, as
+`pino.destination` writes things synchronously.
 
 #### `pino.final(logger, handler) => Function`
 

lib/tools.js

@@ -21,11 +21,6 @@ const {
   streamSym
 } = require('./symbols')
 
-// FIXME we need to check if we are using AWS Lambda
-// because we cannot use pino.destination/Sonic Boom
-// there, as data might get lost during freeze
-const isAWSLambda = !!process.env.LAMBDA_TASK_ROOT
-
 function noop () {}
 
 function genLog (z) {
@@ -267,8 +262,8 @@ function hasBeenTampered (stream) {
   return stream.write !== stream.constructor.prototype.write
 }
 
-function buildSafeSonicBoom (dest, buffer = 0) {
-  const stream = new SonicBoom(dest, buffer)
+function buildSafeSonicBoom (dest, buffer = 0, sync = true) {
+  const stream = new SonicBoom(dest, buffer, sync)
   stream.on('error', filterBrokenPipe)
   return stream
 
@@ -311,7 +306,7 @@ function createArgsNormalizer (defaultOptions) {
     const { enabled, prettyPrint, prettifier, messageKey } = opts
     if (enabled === false) opts.level = 'silent'
     stream = stream || process.stdout
-    if (stream === process.stdout && stream.fd >= 0 && !isAWSLambda && !hasBeenTampered(stream)) {
+    if (stream === process.stdout && stream.fd >= 0 && !hasBeenTampered(stream)) {
       stream = buildSafeSonicBoom(stream.fd)
     }
     if (prettyPrint) {

package.json

@@ -69,7 +69,7 @@
     "fresh-require": "^1.0.3",
     "log": "^1.4.0",
     "loglevel": "^1.6.1",
-    "pino-pretty": "^2.2.4",
+    "pino-pretty": "^2.4.0",
     "pre-commit": "^1.2.2",
     "proxyquire": "^2.1.0",
     "qodaa": "^1.0.1",
@@ -79,17 +79,17 @@
     "steed": "^1.1.3",
     "tap": "^12.1.0",
     "tape": "^4.9.0",
-    "through2": "^2.0.5",
+    "through2": "^3.0.0",
     "winston": "^3.1.0"
   },
   "dependencies": {
     "fast-json-parse": "^1.0.3",
-    "fast-redact": "^1.4.0",
+    "fast-redact": "^1.4.2",
     "fast-safe-stringify": "^2.0.6",
-    "flatstr": "^1.0.5",
+    "flatstr": "^1.0.9",
     "pino-std-serializers": "^2.3.0",
     "pump": "^3.0.0",
     "quick-format-unescaped": "^3.0.0",
-    "sonic-boom": "^0.6.3"
+    "sonic-boom": "^0.7.1"
   }
 }

pino.js

@@ -119,8 +119,8 @@ function pino (...args) {
   return instance
 }
 
-pino.extreme = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 4096)
-pino.destination = (dest = process.stdout.fd) => buildSafeSonicBoom(dest)
+pino.extreme = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 4096, false)
+pino.destination = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 0, true)
 
 pino.final = final
 pino.levels = mappings()

test/exit.test.js

@@ -0,0 +1,53 @@
+'use strict'
+
+const { test } = require('tap')
+const { join } = require('path')
+const execa = require('execa')
+const writer = require('flush-write-stream')
+const { once } = require('./helper')
+
+// https://github.com/pinojs/pino/issues/542
+test('pino.destination log everything when calling process.exit(0)', async ({ isNot }) => {
+  var actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'destination-exit.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+
+  await once(child, 'close')
+
+  isNot(actual.match(/hello/), null)
+  isNot(actual.match(/world/), null)
+})
+
+test('pino.extreme does not log everything when calling process.exit(0)', async ({ is }) => {
+  var actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'extreme-exit.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+
+  await once(child, 'close')
+
+  is(actual.match(/hello/), null)
+  is(actual.match(/world/), null)
+})
+
+test('pino.extreme logs everything when calling flushSync', async ({ isNot }) => {
+  var actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'extreme-flush-exit.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+
+  await once(child, 'close')
+
+  isNot(actual.match(/hello/), null)
+  isNot(actual.match(/world/), null)
+})

test/final.test.js

@@ -24,13 +24,13 @@ test('throws if the supplied handler is not a function', async ({ throws }) => {
   }, Error('if supplied, the handler parameter should be a function'))
 })
 
-test('throws if not supplied logger with pino.destination or pino.extreme instance', async ({ throws, doesNotThrow }) => {
+test('throws if not supplied logger with pino.extreme instance', async ({ throws, doesNotThrow }) => {
   throws(() => {
     pino.final(pino(fs.createWriteStream('/dev/null')), () => {})
   }, Error('final requires a stream that has a flushSync method, such as pino.destination and pino.extreme'))
 
   doesNotThrow(() => {
-    pino.final(pino(pino.destination()), () => {})
+    pino.final(pino(pino.extreme()), () => {})
   })
 
   doesNotThrow(() => {
@@ -39,10 +39,22 @@ test('throws if not supplied logger with pino.destination or pino.extreme instan
 })
 
 test('returns an exit listener function', async ({ is }) => {
-  is(typeof pino.final(pino(pino.destination()), () => {}), 'function')
+  is(typeof pino.final(pino(pino.extreme()), () => {}), 'function')
 })
 
 test('listener function immediately sync flushes when fired', async ({ pass, fail }) => {
+  const dest = pino.extreme('/dev/null')
+  var passed = false
+  dest.flushSync = () => {
+    passed = true
+    pass('flushSync called')
+  }
+  pino.final(pino(dest), () => {})()
+  await sleep(10)
+  if (passed === false) fail('flushSync not called')
+})
+
+test('listener function immediately sync flushes when fired (pino.destination)', async ({ pass, fail }) => {
   const dest = pino.destination('/dev/null')
   var passed = false
   dest.flushSync = () => {
@@ -55,14 +67,14 @@ test('listener function immediately sync flushes when fired', async ({ pass, fai
 })
 
 test('swallows the non-ready error', async ({ doesNotThrow }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   doesNotThrow(() => {
     pino.final(pino(dest), () => {})()
   })
 })
 
 test('listener function triggers handler function parameter', async ({ pass, fail }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   var passed = false
   pino.final(pino(dest), () => {
     passed = true
@@ -73,14 +85,14 @@ test('listener function triggers handler function parameter', async ({ pass, fai
 })
 
 test('passes any error to the handler', async ({ is }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   pino.final(pino(dest), (err) => {
     is(err.message, 'test')
   })(Error('test'))
 })
 
 test('passes a specialized final logger instance', async ({ is, isNot, error }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   const logger = pino(dest)
   pino.final(logger, (err, finalLogger) => {
     error(err)
@@ -104,7 +116,7 @@ test('passes a specialized final logger instance', async ({ is, isNot, error })
 })
 
 test('returns a specialized final logger instance if no handler is passed', async ({ is, isNot }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   const logger = pino(dest)
   const finalLogger = pino.final(logger)
   is(typeof finalLogger.trace, 'function')
@@ -126,7 +138,7 @@ test('returns a specialized final logger instance if no handler is passed', asyn
 })
 
 test('final logger instances synchronously flush after a log method call', async ({ pass, fail, error }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   const logger = pino(dest)
   var passed = false
   var count = 0
@@ -146,7 +158,7 @@ test('final logger instances synchronously flush after a log method call', async
 })
 
 test('also instruments custom log methods', async ({ pass, fail, error }) => {
-  const dest = pino.destination('/dev/null')
+  const dest = pino.extreme('/dev/null')
   const logger = pino({
     customLevels: {
       foo: 35

test/fixtures/destination-exit.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 logger = pino({}, pino.destination(1))
+logger.info('hello')
+logger.info('world')
+process.exit(0)

test/fixtures/extreme-exit.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 dest = pino.extreme(1)
+var logger = pino({}, dest)
+logger.info('hello')
+logger.info('world')
+process.exit(0)

test/fixtures/extreme-flush-exit.js

@@ -0,0 +1,10 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var pino = require(require.resolve('./../../'))
+var dest = pino.extreme(1)
+var logger = pino({}, dest)
+logger.info('hello')
+logger.info('world')
+dest.flushSync()
+process.exit(0)

test/stdout-protection.test.js

@@ -1,34 +1,11 @@
 'use strict'
 
 const { test } = require('tap')
-const pino = require('..')
-const { symbols } = pino
 const { join } = require('path')
 const { fork } = require('child_process')
 const { once } = require('./helper')
 const writer = require('flush-write-stream')
 
-test('do not use SonicBoom on AWS Lambda', async (t) => {
-  // hack, we are on lambda now
-  process.env.LAMBDA_TASK_ROOT = __dirname
-
-  // we need to clear the cache
-  delete require.cache[require.resolve('../')]
-  delete require.cache[require.resolve('../lib/tools.js')]
-  const pino = require('..')
-
-  // restore in the next tick
-  process.nextTick(() => {
-    delete process.env.LAMBDA_TASK_ROOT
-  })
-
-  const logger = pino()
-
-  // this test verifies that the default constructor of pino
-  // does not use SonicBoom on lambda by default
-  t.equal(logger[symbols.streamSym], process.stdout)
-})
-
 test('do not use SonicBoom is someone tampered with process.stdout.write', async ({ isNot }) => {
   var actual = ''
   const child = fork(join(__dirname, 'fixtures', 'stdout-hack-protection.js'), { silent: true })