Async by default (#1448)

* Remove prettyPrint option. 100% code coverage back. * Remove pino.final * Fix jsdom TS issue * Restore lost error * Add link to pino-pretty * Update Node.js in workflows * Async loggic by default Signed-off-by: Matteo Collina <[email protected]> * Update docs/asynchronous.md Co-authored-by: Igor Savin <[email protected]> * Update docs/asynchronous.md Co-authored-by: Igor Savin <[email protected]> * Update docs/asynchronous.md Co-authored-by: James Sumners <[email protected]> * fix flaky test Signed-off-by: Matteo Collina <[email protected]> Co-authored-by: Igor Savin <[email protected]> Co-authored-by: James Sumners <[email protected]>
pinojs · Jun 1, 2022 · 171e102 · 171e102
1 parent 2dcf30e
commit 171e102
Show file tree

Hide file tree

Showing 15 changed files with 83 additions and 144 deletions.
diff --git a/benchmarks/basic.bench.js b/benchmarks/basic.bench.js
@@ -10,7 +10,7 @@ const dest = fs.createWriteStream('/dev/null')
 const loglevel = require('./utils/wrap-log-level')(dest)
 const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', minLength: 4096 }))
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null'))
 
@@ -78,9 +78,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsync (cb) {
+  function benchPinoMinLength (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info('hello world')
+      plogMinLength.info('hello world')
     }
     setImmediate(cb)
   },

diff --git a/benchmarks/child-child.bench.js b/benchmarks/child-child.bench.js
@@ -9,7 +9,7 @@ const plogNodeStream = pino(dest).child({ a: 'property' }).child({ sub: 'child'
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
   .child({ a: 'property' })
   .child({ sub: 'child' })
 
@@ -35,9 +35,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncChildChild (cb) {
+  function benchPinoMinLengthChildChild (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info({ hello: 'world' })
+      plogMinLength.info({ hello: 'world' })
     }
     setImmediate(cb)
   },

diff --git a/benchmarks/child-creation.bench.js b/benchmarks/child-creation.bench.js
@@ -9,7 +9,7 @@ const dest = fs.createWriteStream('/dev/null')
 const plogNodeStream = pino(dest)
 const plogDest = pino(pino.destination(('/dev/null')))
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
 
 const max = 10
 const blog = bunyan.createLogger({
@@ -47,8 +47,8 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncCreation (cb) {
-    const child = plogAsync.child({ a: 'property' })
+  function benchPinoMinLengthCreation (cb) {
+    const child = plogMinLength.child({ a: 'property' })
     for (var i = 0; i < max; i++) {
       child.info({ hello: 'world' })
     }

diff --git a/benchmarks/child.bench.js b/benchmarks/child.bench.js
@@ -10,7 +10,7 @@ const plogNodeStream = pino(dest).child({ a: 'property' })
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null')).child({ a: 'property' })
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
 
 const max = 10
 const blog = bunyan.createLogger({
@@ -45,9 +45,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncChild (cb) {
+  function benchPinoMinLengthChild (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info({ hello: 'world' })
+      plogMinLength.info({ hello: 'world' })
     }
     setImmediate(cb)
   },

diff --git a/benchmarks/deep-object.bench.js b/benchmarks/deep-object.bench.js
@@ -11,7 +11,7 @@ const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
 delete require.cache[require.resolve('../')]
 
 const loglevel = require('./utils/wrap-log-level')(dest)
@@ -71,9 +71,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncDeepObj (cb) {
+  function benchPinoMinLengthDeepObj (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info(deep)
+      plogMinLength.info(deep)
     }
     setImmediate(cb)
   },

diff --git a/benchmarks/long-string.bench.js b/benchmarks/long-string.bench.js
@@ -11,7 +11,7 @@ const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
 
 const crypto = require('crypto')
 
@@ -64,9 +64,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsync (cb) {
+  function benchPinoMinLength (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info(longStr)
+      plogMinLength.info(longStr)
     }
     setImmediate(cb)
   },

diff --git a/benchmarks/multi-arg.bench.js b/benchmarks/multi-arg.bench.js
@@ -11,7 +11,7 @@ const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
 delete require.cache[require.resolve('../')]
 
 const deep = require('../package.json')
@@ -67,9 +67,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncInterpolate (cb) {
+  function benchPinoMinLengthInterpolate (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info('hello %s', 'world')
+      plogMinLength.info('hello %s', 'world')
     }
     setImmediate(cb)
   },
@@ -104,9 +104,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncInterpolateAll (cb) {
+  function benchPinoMinLengthInterpolateAll (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info('hello %s %j %d', 'world', { obj: true }, 4)
+      plogMinLength.info('hello %s %j %d', 'world', { obj: true }, 4)
     }
     setImmediate(cb)
   },
@@ -140,9 +140,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncInterpolateExtra (cb) {
+  function benchPinoMinLengthInterpolateExtra (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info('hello %s %j %d', 'world', { obj: true }, 4, { another: 'obj' })
+      plogMinLength.info('hello %s %j %d', 'world', { obj: true }, 4, { another: 'obj' })
     }
     setImmediate(cb)
   },
@@ -176,9 +176,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncInterpolateDeep (cb) {
+  function benchPinoMinLengthInterpolateDeep (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info('hello %j', deep)
+      plogMinLength.info('hello %j', deep)
     }
     setImmediate(cb)
   },

diff --git a/benchmarks/object.bench.js b/benchmarks/object.bench.js
@@ -12,7 +12,7 @@ const plogNodeStream = pino(dest)
 delete require.cache[require.resolve('../')]
 const plogDest = require('../')(pino.destination('/dev/null'))
 delete require.cache[require.resolve('../')]
-const plogAsync = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
+const plogMinLength = require('../')(pino.destination({ dest: '/dev/null', sync: false, minLength: 4096 }))
 const blog = bunyan.createLogger({
   name: 'myapp',
   streams: [{
@@ -65,9 +65,9 @@ const run = bench([
     }
     setImmediate(cb)
   },
-  function benchPinoAsyncObj (cb) {
+  function benchPinoMinLengthObj (cb) {
     for (var i = 0; i < max; i++) {
-      plogAsync.info({ hello: 'world' })
+      plogMinLength.info({ hello: 'world' })
     }
     setImmediate(cb)
   },

diff --git a/docs/api.md b/docs/api.md
@@ -1000,7 +1000,7 @@ Exposes the Pino package version. Also available on the exported `pino` function
 ### `pino.destination([opts]) => SonicBoom`
 
 Create a Pino Destination instance: a stream-like object with
-significantly more throughput (over 30%) than a standard Node.js stream.
+significantly more throughput than a standard Node.js stream.
 
 ```js
 const pino = require('pino')
@@ -1009,7 +1009,11 @@ const logger2 = pino(pino.destination())
 const logger3 = pino(pino.destination({
   dest: './my-file',
   minLength: 4096, // Buffer before writing
-  sync: false // Asynchronous logging
+  sync: false // Asynchronous logging, the default
+}))
+const logger4 = pino(pino.destination({
+  dest: './my-file2',
+  sync: true // Synchronous logging
 }))
 ```
 

diff --git a/docs/asynchronous.md b/docs/asynchronous.md
@@ -1,11 +1,7 @@
 # Asynchronous Logging
 
-In essence, asynchronous logging enables even faster performance by Pino.
-
-In Pino's standard mode of operation log messages are directly written to the
-output stream as the messages are generated with a _blocking_ operation.
-Asynchronous logging works by buffering
-log messages and writing them in larger chunks.
+In essence, asynchronous logging enables the minimum overhead of Pino.
+Asynchronous logging works by buffering log messages and writing them in larger chunks.
 
 ```js
 const pino = require('pino')
@@ -16,74 +12,19 @@ const logger = pino(pino.destination({
 }))
 ```
 
+It's always possible to turn on synchronous logging by passing `sync: true`. 
+In this mode of operation log messages are directly written to the
+output stream, as the messages are generated with a _blocking_ operation.
+
 * See [`pino.destination`](/docs/api.md#pino-destination)
 * `pino.destination` is implemented on [`sonic-boom` ⇗](https://github.com/mcollina/sonic-boom).
 
 ### AWS Lambda
 
-On AWS Lambda we recommend to call `dest.flushSync()` at the end
+Asynchronous logging is disabled by default on AWS Lambda, or any other environment
+that modifies `process.stdout`. If forcefully turned on, we recommend to call `dest.flushSync()` at the end
 of each function execution to avoid losing data.
 
-## Usage
-
-The `pino.destination({ sync: false })` method will provide an asynchronous destination.
-
-```js
-const pino = require('pino')
-const dest = pino.destination({ sync: false }) // logs to stdout with no args
-const logger = pino(dest)
-```
-
-<a id='log-loss-prevention'></a>
-## Prevent log loss in Node v12
-
-In Node.js v14+, streams created by `pino.destination()` are automatically 
-flushed whenever the process exits.
-In Node v12, `pino.final()` can be used to prevent log loss. Here is an example:
-
-```js
-const pino = require('pino')
-const dest = pino.destination({ sync: false })
-const logger = pino(dest)
-
-// asynchronously flush every 10 seconds to keep the buffer empty
-// in periods of low activity
-setInterval(function () {
-  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) => {
-  finalLogger.info(`${evt} caught`)
-  if (err) finalLogger.error(err, 'error caused exit')
-  process.exit(err ? 1 : 0)
-})
-// 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('SIGINT', () => handler(null, 'SIGINT'))
-process.on('SIGQUIT', () => handler(null, 'SIGQUIT'))
-process.on('SIGTERM', () => handler(null, 'SIGTERM'))
-```
-
-The above code will register handlers for the following process events/signals so that
-pino can flush the asynchronous logger buffer:
-
-+ `beforeExit`
-+ `exit`
-+ `uncaughtException`
-+ `SIGINT`
-+ `SIGQUIT`
-+ `SIGTERM`
-
-In all of these cases, except `SIGHUP`, the process is in a state that it
-*must* terminate. Note that the handler has a `process.exit(1)` at the end.
-
-
-* See also [`pino.final` api](/docs/api.md#pino-final)
-
 ## Caveats
 
 Asynchronous logging has a couple of important caveats:
@@ -92,9 +33,6 @@ Asynchronous logging has a couple of important caveats:
   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
   in case of a system failure, e.g. a power cut.
-* In Node v14+, Pino will register handlers for the `exit` and `beforeExit` handler so that
-  the stream is flushed automatically. This is implemented with the usage of
-  [`on-exit-leak-free`](https://github.com/mcollina/on-exit-leak-free).
 
 See also: