Correct some bunyan CLI exit handling.

This cleans up exit handling and stdout flushing on exit after some
lessons learned with https://github.com/joyent/node-exeunt
This also improves internal bunyan dev debugging via the
`BUNYAN_SELF_TRACE=1` envvar to help trace what was happening with
the issues described in #499.

Fixes #499

CHANGES.md

@@ -5,9 +5,9 @@ Known issues:
 - [issue #58] Can't install to a dir with spaces. This is [this node-gyp
   bug](https://github.com/TooTallNate/node-gyp/issues/65).
 
-## not yet released
+## not yet released (2.x)
 
-(nothing yet)
+- [issue #499] Fix some `bunyan` CLI exit handling problems.
 
 
 ## 1.8.10

bin/bunyan

@@ -26,6 +26,8 @@ var child_process = require('child_process'),
     execFile = child_process.execFile;
 var assert = require('assert');
 
+var exeunt = require('exeunt');
+
 try {
     var moment = require('moment');
 } catch (e) {
@@ -39,7 +41,13 @@ var nodeVer = process.versions.node.split('.').map(Number);
 var nodeSpawnSupportsStdio = (nodeVer[0] > 0 || nodeVer[1] >= 8);
 
 // Internal debug logging via `console.warn`.
-var _DEBUG = false;
+var _selfTrace = function selfTraceNoop() {};
+if (process.env.BUNYAN_SELF_TRACE === "1") {
+    _selfTrace = function selfTrace() {
+        process.stderr.write('[bunyan self-trace] ');
+        console.warn.apply(null, arguments);
+    }
+}
 
 // Output modes.
 var OM_LONG = 1;
@@ -102,6 +110,10 @@ var TIMEZONE_LOCAL_FORMATS = {
 };
 
 
+// Boolean set to true when we are in the process of exiting. We don't always
+// hard-exit (e.g. when staying alive while the pager completes).
+var exiting = false;
+
 // The current raw input line being processed. Used for `uncaughtException`.
 var currLine = null;
 
@@ -710,6 +722,11 @@ var minValidRecord = {
  * records) or enqueues it for emitting later when it's the next line to show.
  */
 function handleLogLine(file, line, opts, stylize) {
+    if (exiting) {
+        _selfTrace('warn: handleLogLine called while exiting');
+        return;
+    }
+
     currLine = line; // intentionally global
 
     // Emit non-JSON lines immediately.
@@ -1091,37 +1108,16 @@ function emitRecord(rec, line, opts, stylize) {
 }
 
 
-var stdoutFlushed = true;
 function emit(s) {
     try {
-        stdoutFlushed = stdout.write(s);
+        stdout.write(s);
-    } catch (e) {
+    } catch (writeErr) {
+        _selfTrace('exception from stdout.write:', writeErr)
         // Handle any exceptions in stdout writing in `stdout.on('error', ...)`.
     }
 }
 
 
-/**
- * A hacked up version of 'process.exit' that will first drain stdout
- * before exiting. *WARNING: This doesn't stop event processing.* IOW,
- * callers have to be careful that code following this call isn't
- * accidentally executed.
- *
- * In node v0.6 "process.stdout and process.stderr are blocking when they
- * refer to regular files or TTY file descriptors." However, this hack might
- * still be necessary in a shell pipeline.
- */
-function drainStdoutAndExit(code) {
-    if (_DEBUG) warn('(drainStdoutAndExit(%d))', code);
-    stdout.on('drain', function () {
-        cleanupAndExit(code);
-    });
-    if (stdoutFlushed) {
-        cleanupAndExit(code);
-    }
-}
-
-
 /**
  * Process all input from stdin.
  *
@@ -1256,7 +1252,7 @@ function processPids(opts, stylize, callback) {
 
             warn('bunyan: error: level (%d) exceeds maximum logging level',
                 opts.level);
-            return drainStdoutAndExit(1);
+            cleanupAndExit(1);
         }).join(',');
         var argv = ['dtrace', '-Z', '-x', 'strsize=4k',
             '-x', 'switchrate=10hz', '-qn',
@@ -1353,6 +1349,12 @@ function processFile(file, opts, stylize, callback) {
 
     var leftover = '';  // Left-over partial line from last chunk.
     stream.on('data', function (data) {
+        if (exiting) {
+            _selfTrace('stop reading file "%s" because exiting', file);
+            stream.destroy();
+            return;
+        }
+
         var chunk = decoder.write(data);
         if (!chunk.length) {
             return;
@@ -1419,22 +1421,21 @@ function asyncForEach(arr, iterator, callback) {
 /**
  * Cleanup and exit properly.
  *
- * Warning: this doesn't stop processing, i.e. process exit might be delayed.
+ * Warning: this doesn't necessarily stop processing, i.e. process exit
- * It is up to the caller to ensure that no subsequent bunyan processing
+ * might be delayed. It is up to the caller to ensure that no subsequent
- * is done after calling this.
+ * bunyan processing is done after calling this.
  *
  * @param code {Number} exit code.
  * @param signal {String} Optional signal name, if this was exitting because
  *    of a signal.
  */
-var cleanedUp = false;
 function cleanupAndExit(code, signal) {
     // Guard one call.
-    if (cleanedUp) {
+    if (exiting) {
         return;
     }
-    cleanedUp = true;
+    exiting = true;
-    if (_DEBUG) warn('(bunyan: cleanupAndExit)');
+    _selfTrace('cleanupAndExit(%s, %s)', code, signal);
 
     // Clear possibly interrupted ANSI code (issue #59).
     if (usingAnsiCodes) {
@@ -1448,16 +1449,22 @@ function cleanupAndExit(code, signal) {
 
     if (pager) {
         // Let pager know that output is done, then wait for pager to exit.
-        stdout.end();
+        pager.removeListener('exit', onPrematurePagerExit);
-        pager.on('exit', function (pagerCode) {
+        pager.on('exit', function onPagerExit(pagerCode) {
-            if (_DEBUG)
+            _selfTrace('pager exit -> process.exit(%s)', pagerCode || code);
-                warn('(bunyan: pager exit -> process.exit(%s))',
-                    pagerCode || code);
             process.exit(pagerCode || code);
         });
-    } else {
+        stdout.end();
-        if (_DEBUG) warn('(bunyan: process.exit(%s))', code);
+    } else if (code) {
+        // Non-zero exit: Something is wrong. We are very likely still
+        // processing log records -- i.e. we have open handles -- so we need
+        // a hard stop (aka `process.exit`).
+        _selfTrace('process.exit(%s)', code);
         process.exit(code);
+    } else {
+        // Zero exit: This should be a "normal" exit, for which we want to
+        // flush stdout/stderr.
+        exeunt.softExit(code);
     }
 }
 
@@ -1510,12 +1517,24 @@ process.on('uncaughtException', function (err) {
 });
 
 
+// Early termination of the pager: just stop.
+function onPrematurePagerExit(pagerCode) {
+    _selfTrace('premature pager exit');
+    // 'pager' and 'stdout' are intentionally global.
+    pager = null;
+    stdout.end()
+    stdout = process.stdout;
+    cleanupAndExit(pagerCode);
+}
+
+
 function main(argv) {
     try {
         var opts = parseArgv(argv);
     } catch (e) {
         warn('bunyan: error: %s', e.message);
-        return drainStdoutAndExit(1);
+        cleanupAndExit(1);
+        return;
     }
     if (opts.help) {
         printHelp();
@@ -1528,7 +1547,8 @@ function main(argv) {
     if (opts.pids && opts.args.length > 0) {
         warn('bunyan: error: can\'t use both "-p PID" (%s) and file (%s) args',
             opts.pids, opts.args.join(' '));
-        return drainStdoutAndExit(1);
+        cleanupAndExit(1);
+        return;
     }
     if (opts.color === null) {
         if (process.env.BUNYAN_NO_COLOR &&
@@ -1568,36 +1588,26 @@ function main(argv) {
             // I'll remove 'F' from here.
             env.LESS = 'FRX';
         }
-        if (_DEBUG) warn('(pager: argv=%j, env.LESS=%j)', argv, env.LESS);
+        _selfTrace('pager: argv=%j, env.LESS=%j', argv, env.LESS);
         // `pager` and `stdout` intentionally global.
         pager = spawn(argv[0], argv.slice(1),
             // Share the stderr handle to have error output come
             // straight through. Only supported in v0.8+.
             {env: env, stdio: ['pipe', 1, 2]});
         stdout = pager.stdin;
-
+        pager.on('exit', onPrematurePagerExit);
-        // Early termination of the pager: just stop.
-        pager.on('exit', function (pagerCode) {
-            if (_DEBUG) warn('(bunyan: pager exit)');
-            pager = null;
-            stdout.end()
-            stdout = process.stdout;
-            cleanupAndExit(pagerCode);
-        });
     }
 
     // Stdout error handling. (Couldn't setup until `stdout` was determined.)
     stdout.on('error', function (err) {
-        if (_DEBUG) warn('(stdout error event: %s)', err);
+        _selfTrace('stdout error event: %s, exiting=%s', err, exiting);
-        if (err.code === 'EPIPE') {
+        if (exiting) {
-            drainStdoutAndExit(0);
+            return;
-        } else if (err.toString() === 'Error: This socket is closed.') {
+        } else if (err.code === 'EPIPE') {
-            // Could get this if the pager closes its stdin, but hasn't
+            cleanupAndExit(0);
-            // exited yet.
-            drainStdoutAndExit(1);
         } else {
-            warn(err);
+            warn('bunyan: error on output stream: %s', err);
-            drainStdoutAndExit(1);
+            cleanupAndExit(1);
         }
     });
 
@@ -1624,9 +1634,10 @@ function main(argv) {
             function (err) {
                 if (err) {
                     warn('bunyan: unexpected error: %s', err.stack || err);
-                    return drainStdoutAndExit(1);
+                    cleanupAndExit(1);
+                } else {
+                    cleanupAndExit(retval);
                 }
-                cleanupAndExit(retval);
             }
         );
     } else {

package.json

@@ -16,6 +16,9 @@
   "keywords": ["log", "logging", "log4j", "json", "bunyan"],
   "license": "MIT",
 
+  "dependencies": {
+    "exeunt": "1.1.0"
+  },
   "// dtrace-provider": "required for dtrace features",
   "// mv": "required for RotatingFileStream",
   "// moment": "required for local time with CLI",
@@ -35,7 +38,5 @@
 
   "scripts": {
     "test": "make test"
-  },
-  "dependencies": {
   }
 }