Repository: pinojs/pino
Pull request #1091 (2021-08-18 15:08:24)

Automatically flush the logs on exit in Node v14+
This PR removes the main developer experience hurdle in using asynchronous logging: the use of `pino.final()`.
Thanks to `on-exit-leak-free` we can automatically flush on exit without leaking event emitter listeners (in most cases).
This uses the same mechanism I experimented with for `pino.transport()`.


Patch:
diff --git a/docs/asynchronous.md b/docs/asynchronous.md
index fd6d935..1096380 100644
--- a/docs/asynchronous.md
+++ b/docs/asynchronous.md
@@ -19,43 +19,6 @@ const logger = pino(pino.destination({
 * See [`pino.destination`](/docs/api.md#pino-destination)
 * `pino.destination` is implemented on [`sonic-boom` ⇗](https://github.com/mcollina/sonic-boom).
 
-## Caveats
-
-This has a couple of important caveats:
-
-* 4KB of spare RAM will be needed for logging
-* As opposed to the default mode, there is not a one-to-one relationship between
-  calls to logging methods (e.g. `logger.info`) and writes to a log file
-* There is a possibility of the most recently buffered log messages being lost
-  (up to 4KB of logs)
-  * For instance, a power cut will mean up to 4KB of buffered logs will be lost
-
-So in summary, use asynchronous logging only when performing an extreme amount of
-logging, and it is acceptable to potentially lose the most recent logs.
-
-* Pino will register handlers for the following process events/signals so that
-  Pino can flush the asynchronous logger buffer:
-
-  + `beforeExit`
-  + `exit`
-  + `uncaughtException`
-  + `SIGHUP`
-  + `SIGINT`
-  + `SIGQUIT`
-  + `SIGTERM`
-
-  In all of these cases, except `SIGHUP`, the process is in a state that it
-  *must* terminate. Thus, if an `onTerminated` function isn't registered when
-  constructing a Pino instance (see [pino#constructor](api.md#constructor)),
-  then Pino will invoke `process.exit(0)` when no error has occurred, or
-  `process.exit(1)` otherwise. If an `onTerminated` function is supplied, it
-  is the responsibility of the `onTerminated` function to manually exit the process.
-
-  In the case of `SIGHUP`, we will look to see if any other handlers are
-  registered for the event. If not, we will proceed as we do with all other
-  signals. If there are more handlers registered than just our own, we will
-  simply flush the asynchronous logging buffer.
-
 ### AWS Lambda
 
 On AWS Lambda we recommend to call `dest.flushSync()` at the end
@@ -103,6 +66,45 @@ process.on('SIGQUIT', () => handler(null, 'SIGQUIT'))
 process.on('SIGTERM', () => handler(null, 'SIGTERM'))
 ```
 
+Note that the use of `pino.final` is not strictly required when using Node v14+.
+
+## Caveats
+
+This has a couple of important caveats:
+
+* 4KB of spare RAM will be needed for logging
+* As opposed to the default mode, there is not a one-to-one relationship between
+  calls to logging methods (e.g. `logger.info`) and writes to a log file
+* There is a possibility of the most recently buffered log messages being lost
+  (up to 4KB of logs)
+  * For instance, a power cut will mean up to 4KB of buffered logs will be lost
+
+So in summary, use asynchronous logging only when performing an extreme amount of
+logging, and it is acceptable to potentially lose the most recent logs.
+
+* Pino will register handlers for the following process events/signals so that
+  Pino can flush the asynchronous logger buffer:
+
+  + `beforeExit`
+  + `exit`
+  + `uncaughtException`
+  + `SIGHUP`
+  + `SIGINT`
+  + `SIGQUIT`
+  + `SIGTERM`
+
+  In all of these cases, except `SIGHUP`, the process is in a state that it
+  *must* terminate. Thus, if an `onTerminated` function isn't registered when
+  constructing a Pino instance (see [pino#constructor](api.md#constructor)),
+  then Pino will invoke `process.exit(0)` when no error has occurred, or
+  `process.exit(1)` otherwise. If an `onTerminated` function is supplied, it
+  is the responsibility of the `onTerminated` function to manually exit the process.
+
+  In the case of `SIGHUP`, we will look to see if any other handlers are
+  registered for the event. If not, we will proceed as we do with all other
+  signals. If there are more handlers registered than just our own, we will
+  simply flush the asynchronous logging buffer.
+
 * See [`pino.destination` api](/docs/api.md#pino-destination)
 * See [`pino.final` api](/docs/api.md#pino-final)
 * See [`destination` parameter](/docs/api.md#destination)
diff --git a/lib/tools.js b/lib/tools.js
index eff5f17..82b9eb7 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -25,6 +25,7 @@ const {
   messageKeySym,
   nestedKeyStrSym
 } = require('./symbols')
+const { isMainThread } = require('worker_threads')
 
 function noop () {}
 
@@ -330,6 +331,10 @@ function hasBeenTampered (stream) {
 function buildSafeSonicBoom (opts) {
   const stream = new SonicBoom(opts)
   stream.on('error', filterBrokenPipe)
+  // if we are sync: false, we must flush on exit
+  if (!opts.sync && isMainThread) {
+    setupOnExit(stream)
+  }
   return stream
 
   function filterBrokenPipe (err) {
@@ -349,6 +354,39 @@ function buildSafeSonicBoom (opts) {
   }
 }
 
+function setupOnExit (stream) {
+  /* istanbul ignore next */
+  if (global.WeakRef && global.WeakMap && global.FinalizationRegistry) {
+    // This is leak free, it does not leave event handlers
+    const onExit = require('on-exit-leak-free')
+
+    onExit.register(stream, autoEnd)
+
+    stream.on('close', function () {
+      onExit.unregister(stream)
+    })
+  }
+}
+
+function autoEnd (stream, eventName) {
+  // This check is needed only on some platforms
+  /* istanbul ignore next */
+  if (stream.destroyed) {
+    return
+  }
+
+  if (eventName === 'beforeExit') {
+    // We still have an event loop, let's use it
+    stream.flush()
+    stream.on('drain', function () {
+      stream.end()
+    })
+  } else {
+    // We do not have an event loop, so flush synchronously
+    stream.flushSync()
+  }
+}
+
 function createArgsNormalizer (defaultOptions) {
   return function normalizeArgs (instance, opts = {}, stream) {
     // support stream as a string


Test patch:
diff --git a/test/exit.test.js b/test/exit.test.js
index 26ca6db..36eca72 100644
--- a/test/exit.test.js
+++ b/test/exit.test.js
@@ -37,7 +37,9 @@ test('pino with no args log everything when calling process.exit(0)', async ({ n
   not(actual.match(/world/), null)
 })
 
-test('sync false does not log everything when calling process.exit(0)', async ({ equal }) => {
+const hasWeak = !!global.WeakRef
+
+test('sync false does not log everything when calling process.exit(0)', { skip: hasWeak }, async ({ equal }) => {
   let actual = ''
   const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'syncfalse-exit.js')])
 
@@ -52,6 +54,21 @@ test('sync false does not log everything when calling process.exit(0)', async ({
   equal(actual.match(/world/), null)
 })
 
+test('sync false logs everything when calling process.exit(0)', { skip: !hasWeak }, async ({ not }) => {
+  let actual = ''
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'syncfalse-exit.js')])
+
+  child.stdout.pipe(writer((s, enc, cb) => {
+    actual += s
+    cb()
+  }))
+
+  await once(child, 'close')
+
+  not(actual.match(/hello/), null)
+  not(actual.match(/world/), null)
+})
+
 test('sync false logs everything when calling flushSync', async ({ not }) => {
   let actual = ''
   const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'syncfalse-flush-exit.js')])
diff --git a/test/final.test.js b/test/final.test.js
index 65d2f29..300f59d 100644
--- a/test/final.test.js
+++ b/test/final.test.js
@@ -4,6 +4,10 @@ const fs = require('fs')
 const { test } = require('tap')
 const { sleep, getPathToNull } = require('./helper')
 
+// This test is too fast for the GC to trigger the removal, so a leak warning
+// will be emitted. Let's raise this so we do not scare everybody.
+process.setMaxListeners(100)
+
 test('replaces onTerminated option', async ({ throws }) => {
   throws(() => {
     pino({
@@ -48,6 +52,7 @@ test('listener function immediately sync flushes when fired (sync false)', async
   dest.flushSync = () => {
     passed = true
     pass('flushSync called')
+    dest.flushSync = () => {}
   }
   pino.final(pino(dest), () => {})()
   await sleep(10)
@@ -60,6 +65,7 @@ test('listener function immediately sync flushes when fired (sync true)', async
   dest.flushSync = () => {
     passed = true
     pass('flushSync called')
+    dest.flushSync = () => {}
   }
   pino.final(pino(dest), () => {})()
   await sleep(10)