Repository: pinojs/pino
Pull request #187 (2017-02-07 23:07:46)

PR to solve issue #92
- [x] tests waiting for file descriptors
- [x] tests logs are output when event loop isn't really a loop
- [x] removes unexpected call to `process.exit`

In the current state, it solves #131. But it does not fully address #92.

I have created this PR so that we can think on the problem together. Please provide your suggestions, or some commits.


Patch:
diff --git a/.gitignore b/.gitignore
index 506628c..cf3b91f 100644
--- a/.gitignore
+++ b/.gitignore
@@ -41,4 +41,7 @@ profile-*
 
 # JetBrains IntelliJ IDEA
 .idea
-*.iml
\ No newline at end of file
+*.iml
+
+# VS Code
+.vscode/
diff --git a/.travis.yml b/.travis.yml
index 2ed6a38..5301fe6 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -2,7 +2,6 @@ language: node_js
 sudo: false
 node_js:
 - '4'
-- '5'
 - '6'
 - '7'
 script:
diff --git a/docs/API.md b/docs/API.md
index 336e1d4..1e4d7fe 100644
--- a/docs/API.md
+++ b/docs/API.md
@@ -55,6 +55,11 @@
     integer value to define the new level. Default: `undefined`.
   * `prettyPrint` (boolean|object): enables [pino.pretty](#pretty). This is intended for non-production
     configurations. This may be set to a configuration object as outlined in [pino.pretty](#pretty). Default: `false`.
+  * `onTerminated` (function): this function will be invoked during process shutdown when `extreme` is set to `true`.
+    The signature of the function is `onTerminated(eventName, err)`. If you do not specify a function, Pino will
+    invoke `process.exit(0)` when no error has occurred, and `process.exit(1)` otherwise. If you do specify a function,
+    it is up to you to terminate the process; you **must** perform only synchronous operations at this point.
+    See [Extreme mode explained](extreme.md) for more detail.
   * `enabled` (boolean): enables logging. Default: `true`
 + `stream` (Writable): a writable stream where the logs will be written.
   Deafult: `process.stdout`
diff --git a/docs/extreme.md b/docs/extreme.md
index 2996d21..bf4f6e3 100644
--- a/docs/extreme.md
+++ b/docs/extreme.md
@@ -37,6 +37,28 @@ This has a couple of important caveats:
     process.exit(1)
   })
   ```
+* Pino will register handlers for the following process events/signals so that
+  Pino can flush the extreme mode 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 you do not register an `onTerminated` function when
+  constructing your 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 you do supply an `onTerminated` function, it
+  is left up to you to fully terminate 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 extreme mode buffer.
 
 So in summary, only use extreme mode if you're doing an extreme amount of
 logging, and you're happy in some scenarios to lose the most recent logs.
\ No newline at end of file
diff --git a/lib/events.js b/lib/events.js
index 998bc1e..c233a2f 100644
--- a/lib/events.js
+++ b/lib/events.js
@@ -1,29 +1,37 @@
 'use strict'
 
-var once = require('once')
+module.exports = function (pinoInstance, internalExtremeHandler) {
+  function theWorldIsBurning (err) {
+    runInternalHandler()
+    handlers.handledOnTerminate = true
+    pinoInstance.onTerminated(this.name, err)
+  }
 
-function onExit (fn) {
-  var oneFn = once(fn)
-  process.on('beforeExit', handle('beforeExit'))
-  process.on('exit', handle('exit'))
-  process.on('uncaughtException', handle('uncaughtException', 1))
-  process.on('SIGHUP', handle('SIGHUP', 129))
-  process.on('SIGINT', handle('SIGINT', 130))
-  process.on('SIGQUIT', handle('SIGQUIT', 131))
-  process.on('SIGTERM', handle('SIGTERM', 143))
-  function handle (evt, code) {
-    onExit.passCode = function (code) {
-      if (oneFn.value) { oneFn = once(fn) }
-      oneFn(code, evt)
-    }
-    onExit.insertCode = function () {
-      if (oneFn.value) { oneFn = once(fn) }
-      oneFn(code, evt)
+  function hup (err) {
+    if (process.listenerCount('SIGHUP') === 1) {
+      return theWorldIsBurning.call({name: 'SIGHUP'}, err)
     }
-    return (code === undefined) ? onExit.passCode : onExit.insertCode
+    pinoInstance.flush()
   }
-}
 
-module.exports = {
-  onExit: onExit
+  function runInternalHandler () {
+    if (handlers.handledOnTerminate) return
+    internalExtremeHandler()
+  }
+
+  var handlers = {
+    beforeExit: theWorldIsBurning.bind({name: 'beforeExit'}),
+    exit: theWorldIsBurning.bind({name: 'exit'}),
+    uncaughtException: theWorldIsBurning.bind({name: 'uncaughtException'}),
+    SIGHUP: hup,
+    SIGINT: theWorldIsBurning.bind({name: 'SIGINT'}),
+    SIGQUIT: theWorldIsBurning.bind({name: 'SIGQUIT'}),
+    SIGTERM: theWorldIsBurning.bind({name: 'SIGTERM'})
+  }
+
+  Object.keys(handlers).forEach(function (k) {
+    process.on(k, handlers[k])
+  })
+
+  return handlers
 }
diff --git a/lib/tools.js b/lib/tools.js
index 348703c..8a8261c 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -30,6 +30,7 @@ function applyOptions (opts) {
   this.chindings = opts.chindings
   this.cache = opts.cache
   this.formatOpts = opts.formatOpts
+  this.onTerminated = opts.onTerminated
 
   if (opts.level && opts.levelVal) {
     var levelIsStandard = levels.isStandardLevel(opts.level)
diff --git a/package.json b/package.json
index d11d3ce..ce2f085 100644
--- a/package.json
+++ b/package.json
@@ -67,7 +67,7 @@
     "pump": "^1.0.1",
     "standard": "^8.6.0",
     "steed": "^1.1.3",
-    "tap": "^9.0.0",
+    "tap": "^10.0.0",
     "tape": "^4.6.2",
     "through2": "^2.0.1",
     "winston": "^2.3.0",
@@ -78,7 +78,6 @@
     "fast-json-parse": "^1.0.0",
     "fast-safe-stringify": "^1.1.3",
     "flatstr": "^1.0.4",
-    "once": "^1.3.3",
     "pump": "^1.0.2",
     "quick-format-unescaped": "^1.0.0",
     "split2": "^2.0.1"
diff --git a/pino.js b/pino.js
index ffcdfaf..e010dab 100644
--- a/pino.js
+++ b/pino.js
@@ -23,6 +23,10 @@ var defaultOptions = {
   level: 'info',
   levelVal: undefined,
   prettyPrint: false,
+  onTerminated: function (eventName, err) {
+    if (err) return process.exit(1)
+    process.exit(0)
+  },
   enabled: true
 }
 
@@ -59,36 +63,32 @@ function pino (opts, stream) {
     iopts.level = 'silent'
   }
 
-  var logger = new Pino(iopts, istream)
-  if (iopts.cache) {
-    // setImmediate is causing a very weird crash:
-    //    Assertion failed: (cb_v->IsFunction()), function MakeCallback...
-    // but setTimeout isn't *shrug*
-    setTimeout(function () {
-      if (!tools.streamIsBlockable(istream)) {
-        logger.emit('error', new Error('stream must have a file descriptor in extreme mode'))
-      }
-    }, 100)
-
-    events.onExit(function (code, evt) {
-      var buf = iopts.cache.buf
-      if (buf) {
-        // We need to block the process exit long enough to flush the buffer
-        // to the destination stream. We do that by forcing a synchronous
-        // write directly to the stream's file descriptor.
-        var fd = (istream.fd) ? istream.fd : istream._handle.fd
-        fs.writeSync(fd, buf)
-      }
-      if (!process._events[evt] || process._events[evt].length < 2 || !process._events[evt].filter(function (f) {
-        return f + '' !== events.onExit.passCode + '' && f + '' !== events.onExit.insertCode + ''
-      }).length) {
-        process.exit(code)
-      } else {
-        return 'no exit'
-      }
-    })
+  var settleTries = 0
+  function waitForFDSettle () {
+    var isBlockable = tools.streamIsBlockable(istream)
+    if (isBlockable === false && settleTries > 10) {
+      return logger.emit('error', Error('stream must have a file descriptor in extreme mode'))
+    } else if (isBlockable === true) {
+      return events(logger, extremeModeExitHandler)
+    }
+    settleTries += 1
+    setTimeout(waitForFDSettle, 100)
+  }
+
+  function extremeModeExitHandler () {
+    var buf = iopts.cache.buf
+    if (buf) {
+      // We need to block the process exit long enough to flush the buffer
+      // to the destination stream. We do that by forcing a synchronous
+      // write directly to the stream's file descriptor.
+      var fd = (istream.fd) ? istream.fd : istream._handle.fd
+      fs.writeSync(fd, buf)
+    }
   }
 
+  var logger = new Pino(iopts, istream)
+  if (iopts.cache) setTimeout(waitForFDSettle, 100)
+
   return logger
 }
 


Test patch:
diff --git a/test/events.test.js b/test/events.test.js
new file mode 100644
index 0000000..a0d04a1
--- /dev/null
+++ b/test/events.test.js
@@ -0,0 +1,130 @@
+'use strict'
+
+var test = require('tap').test
+var path = require('path')
+var writeStream = require('flush-write-stream')
+var fork = require('child_process').fork
+var spawn = require('child_process').spawn
+var fixturesPath = path.join(__dirname, 'fixtures', 'events')
+
+test('no event loop logs successfully', function (t) {
+  t.plan(1)
+  var output = ''
+  var child = fork(path.join(fixturesPath, 'no-event-loop.js'), {silent: true})
+
+  child.stdout.pipe(writeStream(function (s, enc, cb) {
+    output += s
+    cb()
+  }))
+
+  child.on('close', function () {
+    t.notEqual(output.match(/"msg":"h"/), null)
+  })
+})
+
+test('handles no file descriptor in extreme mode', function (t) {
+  t.plan(2)
+  var output = ''
+  var errorOutput = ''
+  var child = fork(path.join(fixturesPath, 'no-fd.js'), {silent: true})
+
+  child.stdout.pipe(writeStream(function (s, enc, cb) {
+    output += s
+    cb()
+  }))
+
+  child.stderr.pipe(writeStream(function (s, enc, cb) {
+    errorOutput += s
+    cb()
+  }))
+
+  child.on('close', function () {
+    t.is(output, '')
+    t.notEqual(errorOutput.match(/stream must have/g), null)
+  })
+})
+
+test('terminates when uncaughtException is fired with onTerminate registered', function (t) {
+  t.plan(3)
+  var output = ''
+  var errorOutput = ''
+  var child = spawn(process.argv[0], [path.join(fixturesPath, 'uncaughtException.js')], {silent: true})
+
+  child.stdout.pipe(writeStream(function (s, enc, cb) {
+    output += s
+    cb()
+  }))
+
+  child.stderr.pipe(writeStream(function (s, enc, cb) {
+    errorOutput += s
+    cb()
+  }))
+
+  child.on('close', function () {
+    t.notEqual(output.match(/"msg":"h"/), null)
+    t.notEqual(output.match(/terminated/g), null)
+    t.notEqual(errorOutput.match(/this is not caught/g), null)
+  })
+})
+
+test('terminates when uncaughtException is fired without onTerminate registered', function (t) {
+  t.plan(2)
+  var output = ''
+  var child = spawn(process.argv[0], [path.join(fixturesPath, 'uncaughtException-noTerminate.js')], {silent: true})
+
+  child.stdout.pipe(writeStream(function (s, enc, cb) {
+    output += s
+    cb()
+  }))
+
+  child.on('exit', function (code) {
+    t.is(code, 1)
+  })
+
+  child.on('close', function () {
+    t.notEqual(output.match(/"msg":"h"/), null)
+  })
+})
+
+test('terminates on SIGHUP when no other handlers registered', function (t) {
+  t.plan(2)
+  var output = ''
+  var child = spawn(process.argv[0], [path.join(fixturesPath, 'sighup-no-handler.js')], {silent: true})
+
+  child.stdout.pipe(writeStream(function (s, enc, cb) {
+    output += s
+    cb()
+  }))
+
+  child.on('exit', function (code) {
+    t.is(code, 0)
+  })
+
+  child.on('close', function () {
+    t.notEqual(output.match(/"msg":"h"/), null)
+  })
+
+  setTimeout(function () { child.kill('SIGHUP') }, 1000)
+})
+
+test('lets app terminate when SIGHUP received with multiple handlers', function (t) {
+  t.plan(3)
+  var output = ''
+  var child = spawn(process.argv[0], [path.join(fixturesPath, 'sighup-with-handler.js')], {silent: true})
+
+  child.stdout.pipe(writeStream(function (s, enc, cb) {
+    output += s
+    cb()
+  }))
+
+  child.on('exit', function (code) {
+    t.is(code, 0)
+  })
+
+  child.on('close', function () {
+    t.notEqual(output.match(/"msg":"h"/), null)
+    t.notEqual(output.match(/app sighup/), null)
+  })
+
+  setTimeout(function () { child.kill('SIGHUP') }, 1000)
+})
diff --git a/test/fixtures/events/no-event-loop.js b/test/fixtures/events/no-event-loop.js
new file mode 100644
index 0000000..ffd8f95
--- /dev/null
+++ b/test/fixtures/events/no-event-loop.js
@@ -0,0 +1,6 @@
+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({extreme: true})
+log.info('h')
diff --git a/test/fixtures/events/no-fd.js b/test/fixtures/events/no-fd.js
new file mode 100644
index 0000000..4742001
--- /dev/null
+++ b/test/fixtures/events/no-fd.js
@@ -0,0 +1,9 @@
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+var stream = require('stream')
+var dest = new stream.PassThrough()
+dest.pipe(process.stdout)
+var pino = require(require.resolve('./../../../'))
+var log = pino({extreme: true}, dest)
+log.info('h')
diff --git a/test/fixtures/events/sighup-no-handler.js b/test/fixtures/events/sighup-no-handler.js
new file mode 100644
index 0000000..e372aea
--- /dev/null
+++ b/test/fixtures/events/sighup-no-handler.js
@@ -0,0 +1,22 @@
+'use strict'
+
+// we need stable data to run our tests
+global.process = { __proto__: process, pid: 123456 }
+Date.now = function () { return 1459875739796 }
+require('os').hostname = function () { return 'abcdefghijklmnopqr' }
+
+var pino = require(require.resolve('./../../../'))
+
+if (process.listenerCount('SIGHUP') > 0) {
+  // needed because of a hook added by code coverage
+  process.removeAllListeners('SIGHUP')
+}
+
+// extreme mode
+var log = pino({extreme: true})
+log.info('h')
+
+function foo () {
+  setTimeout(foo, 50)
+}
+foo()
diff --git a/test/fixtures/events/sighup-with-handler.js b/test/fixtures/events/sighup-with-handler.js
new file mode 100644
index 0000000..fa08401
--- /dev/null
+++ b/test/fixtures/events/sighup-with-handler.js
@@ -0,0 +1,16 @@
+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({extreme: true})
+log.info('h')
+
+process.on('SIGHUP', function () {
+  console.log('app sighup')
+  process.exit(0)
+})
+
+function foo () {
+  setTimeout(foo, 50)
+}
+foo()
diff --git a/test/fixtures/events/uncaughtException-noTerminate.js b/test/fixtures/events/uncaughtException-noTerminate.js
new file mode 100644
index 0000000..45f0d67
--- /dev/null
+++ b/test/fixtures/events/uncaughtException-noTerminate.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({extreme: true})
+log.info('h')
+
+setTimeout(function () { throw Error('this is not caught') }, 500)
diff --git a/test/fixtures/events/uncaughtException.js b/test/fixtures/events/uncaughtException.js
new file mode 100644
index 0000000..25ac1bc
--- /dev/null
+++ b/test/fixtures/events/uncaughtException.js
@@ -0,0 +1,15 @@
+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({
+  extreme: true,
+  onTerminated: function (evt, err) {
+    console.error(err.message)
+    console.log('terminated')
+    process.exit()
+  }
+})
+log.info('h')
+
+setTimeout(function () { throw Error('this is not caught') }, 500)