pino.final

docs/api.md

@@ -21,6 +21,7 @@
 * [Statics](#statics)
   * [pino.destination()](#pino-destination)
   * [pino.extreme()](#pino-extreme)
+  * [pino.final()](#pino-final)
   * [pino.stdSerializers](#pino-stdserializers)
   * [pino.stdTimeFunctions](#pino-stdtimefunctions)
   * [pino.symbols](#pino-symbols)
@@ -157,26 +158,6 @@ Default: `'msg'`
 
 The string key for the 'message' in the JSON object. 
 
-<a id=onterminated></a>
-#### `onTerminated` (Function)
-
-Default: `(evt, err) => err ? process.exit(1) : process.exit(0)`
-
-This function will be invoked during process shutdown when 
-the supplied destination is an instance of [`pino.extreme`](#pino-extreme)
-
-The signature of the function is `onTerminated(eventName, err)`. 
-
-By default, when `pino.extreme` is used, the `onTerminated` function 
-is set to call `process.exit(1)` on error or else `process.exit(0)`. 
-
-If a function is specified it **must** perform only synchronous operations 
-at this point and then exit the process (there are no ticks left for 
-asynchronous activity at this point in the process lifetime).
-
-* See [pino.extreme](#pino-extreme)
-* See [Extreme mode ⇗](/docs/extreme.md)
-
 <a id=prettyPrint></a>
 #### `prettyPrint` (Boolean | Object)
 
@@ -647,6 +628,29 @@ module.
 * See [`sonic-boom` ⇗](https://github.com/mcollina/sonic-boom)
 * See [Extreme mode ⇗](/docs/extreme.md)
 
+<a id="pino-final"></a>
+### `pino.final(logger, handler) => Function`
+
+The `pino.final` method supplies an exit listener function that can be 
+supplied to process exit events such as `exit`, `uncaughtException`, 
+`SIGHUP` and so on. 
+
+The exit listener function will call the supplied `handler` function 
+with a `finalLogger` instance. The `finalLogger` is a specialist 
+logger that synchronously flushes on every write. This is important 
+to gaurantee final log writes, both when using `pino.destination` or
+`pino.extreme` targets. 
+
+Since final log writes cannot be gauranteed 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.
+
+* See [`destination` parameter](#destination)
+* See [Exit logging help](/docs/help.md#exit-logging)
+* See [Extreme mode ⇗](/docs/extreme.md)
+
 <a id="pino-stdserializers"></a>
 ### `pino.stdSerializers` (Object)
 

docs/extreme.md

@@ -6,6 +6,8 @@ In Pino's standard mode of operation log messages are directly written to the
 output stream as the messages are generated. Extereme mode works by buffering
 log messages and writing them in larger chunks.
 
+## Caveats
+
 This has a couple of important caveats:
 
 * 4KB of spare RAM will be needed for logging
@@ -14,6 +16,10 @@ This has a couple of important caveats:
 * 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, only use extreme mode 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 extreme mode buffer:
 
@@ -37,36 +43,52 @@ This has a couple of important caveats:
   signals. If there are more handlers registered than just our own, we will
   simply flush the extreme mode buffer.
 
-So in summary, only use extreme mode when performing an extreme amount of
-logging and it is acceptable to potentially lose the most recent logs.
-
 ## Usage
 
-Extreme mode is defined by creating an extreme mode destination with
-`pino.extreme()`.
-
-The following creates an extreme destination to stdout:
+The `pino.extreme()` method will provide an Extreme Mode destination.
 
 ```js
-'use strict'
+const pino = require('pino')
+const dest = pino.extreme() // logs to stdout with no args
+const logger = pino(dest)
+```
 
+## Log loss prevention
+
+The following strategy can be used to minimize log loss:
+
+```js
 const pino = require('pino')
 const dest = pino.extreme() // no arguments
 const logger = pino(dest)
 
+// flush every 10 seconds to keep the buffer empty 
+// in periods of low activity
 setInterval(function () {
-  // flush is asynchronous
-  dest.flush()
+  logger.flush()
 }, 10000).unref()
+
+// use pino.final to create a special logger that 
+// guarantees final tick writes 
+const handler = pino.final(logger, (err, finalLogger, evt) => {
+  if (err) finalLogger.error(err, 'error caused exit')
+  finalLogger.info(`${evt} caught`)
+})
+// catch all the ways node might exit
+process.on('beforeExit', () => handler(null, 'beforeExit'))
+process.on('exit', () => handler(null, 'exit'))
+process.on('uncaughtException', (err) => handler(err, 'uncaughtException'))
+process.on('SIGHUP', () => handler(null, 'SIGHUP'))
+process.on('SIGINT', () => handler(null, 'SIGINT'))
+process.on('SIGQUIT', () => handler(null, 'SIGQUIT'))
+process.on('SIGTERM', () => handler(null, 'SIGTERM'))
 ```
 
 An extreme destination is an instance of
 [`SonicBoom`](https://github.com/mcollina/sonic-boom) with `4096`
 buffering.
 
-In case a synchronous flush is needed, `dest.flushSync()` can be called.
-This method might cause some data loss if a write was already in
-progress, so use it only if truly needed.
 
 * See [`pino.extreme` api](/docs/api.md#pino-extreme)
+* See [`pino.final` api](/docs/api.md#pino-final)
 * See [`destination` parameter](/docs/api.md#destination)

docs/help.md

@@ -1,5 +1,6 @@
 # Help
 
+* [Exit logging](#exit-logging)
 * [Log rotation](#rotate)
 * [Saving to multiple files](#multiple)
 * [Log Filtering](#filter-logs)
@@ -8,6 +9,28 @@
 * [Log levels as labels instead of numbers](#level-string)
 * [Pino with `debug`](#debug)
 
+<a id="exit-logging"></a>
+## Exit logging
+
+When a Node process crashes from uncaught exception, exits due to a signal, 
+or exits of it's own accord we may want to write some final logs – particularly
+in cases of error. 
+
+Writing to a Node.js stream on exit is not necessarily guaranteed, and naively writing
+to an Extreme Mode logger on exit will definitely lead to lost logs. 
+
+To write logs in an exit handler, create the handler with `pino.final`:
+
+```js
+process.on('uncaughtException', pino.final(logger, (err, finalLogger) => {
+  finalLogger.error(err)
+}))
+```
+
+The `finalLogger` is a special logger instance that will synchronously and reliably 
+flush every log line. This is important in exit handlers, since no more asynchronous
+activity may be scheduled.
+
 <a id="rotate"></a>
 ## Log rotation
 

lib/proto.js

@@ -100,5 +100,5 @@ function write (obj, msg, num) {
 
 function flush () {
   const stream = this[streamSym]
-  if ('flushSync' in stream) stream.flushSync()
+  if ('flush' in stream) stream.flush()
 }

lib/symbols.js

@@ -19,7 +19,6 @@ const stringifySym = Symbol('pino.stringify')
 const stringifiersSym = Symbol('pino.stringifiers')
 const endSym = Symbol('pino.end')
 const formatOptsSym = Symbol('pino.formatOpts')
-const onTerminatedSym = Symbol('pino.onTerminated')
 const messageKeyStringSym = Symbol('pino.messageKeyString')
 
 const wildcardGsym = Symbol.for('pino.*')
@@ -42,7 +41,6 @@ module.exports = {
   stringifiersSym,
   endSym,
   formatOptsSym,
-  onTerminatedSym,
   messageKeyStringSym,
   wildcardGsym,
   needsMetadataGsym

lib/tools.js

@@ -15,7 +15,8 @@ const {
   stringifiersSym,
   stringifySym,
   needsMetadataGsym,
-  wildcardGsym
+  wildcardGsym,
+  streamSym
 } = require('./symbols')
 
 function noop () {}
@@ -181,7 +182,10 @@ function createArgsNormalizer (defaultOptions) {
     }
     opts = Object.assign({}, defaultOptions, opts)
     if ('extreme' in opts) {
-      throw new Error('The extreme option has been removed, use require(\'pino\').extreme(dest) instead')
+      throw Error('The extreme option has been removed, use pino.extreme instead')
+    }
+    if ('onTerminated' in opts) {
+      throw Error('The onTerminated option has been removed, use pino.final instead')
     }
     const { enabled, prettyPrint, prettifier, messageKey } = opts
     if (enabled === false) opts.level = 'silent'
@@ -197,11 +201,48 @@ function createArgsNormalizer (defaultOptions) {
   }
 }
 
+function final (logger, handler) {
+  if (typeof logger === 'undefined' || typeof logger.child !== 'function') {
+    throw Error('expected a pino logger instance')
+  }
+  if (typeof handler !== 'function') {
+    throw Error('expected a handler function')
+  }
+  const stream = logger[streamSym]
+  if (!(stream instanceof SonicBoom)) {
+    throw Error('only compatible with loggers with pino.destination and pino.extreme targets')
+  }
+
+  return (err = null, ...args) => {
+    try {
+      stream.flushSync()
+    } catch (e) {
+      // it's too late to wait for the stream to be ready
+      // because this is a final tick scenario.
+      // in practice there shouldn't be a situation where it isn't
+      // however, swallow the error just in case (and for easier testing)
+    }
+    const finalLogger = new Proxy(logger, {
+      get: (logger, key) => {
+        if (key in logger.levels.values) {
+          return (...args) => {
+            logger[key](...args)
+            stream.flushSync()
+          }
+        }
+        return logger[key]
+      }
+    })
+    return handler(err, finalLogger, ...args)
+  }
+}
+
 module.exports = {
   noop,
   getPrettyStream,
   asChindings,
   asJson,
   genLog,
-  createArgsNormalizer
+  createArgsNormalizer,
+  final
 }

package.json

@@ -23,7 +23,7 @@
     "bench": "node benchmarks/utils/runbench all",
     "bench-basic": "node benchmarks/utils/runbench basic",
     "bench-object": "node benchmarks/utils/runbench object",
-    "bench-deepo-bject": "node benchmarks/utils/runbench deep-object",
+    "bench-deep-object": "node benchmarks/utils/runbench deep-object",
     "bench-multi-arg": "node benchmarks/utils/runbench multi-arg",
     "bench-longs-tring": "node benchmarks/utils/runbench long-string",
     "bench-child": "node benchmarks/utils/runbench child",