From 0d62f8a890341c1bf99b3a298af068853fc4f82a Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 3 May 2017 23:21:59 -0700 Subject: [PATCH] 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 | 4 +- bin/bunyan | 137 ++++++++++++++++++++++++++++----------------------- package.json | 5 +- 3 files changed, 79 insertions(+), 67 deletions(-) diff --git a/CHANGES.md b/CHANGES.md index 0be116c..7bb3f59 100644 --- a/CHANGES.md +++ b/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 diff --git a/bin/bunyan b/bin/bunyan index 330e25a..fa92807 100755 --- a/bin/bunyan +++ b/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); - } catch (e) { + stdout.write(s); + } 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. - * It is up to the caller to ensure that no subsequent bunyan processing - * is done after calling this. + * Warning: this doesn't necessarily stop processing, i.e. process exit + * might be delayed. It is up to the caller to ensure that no subsequent + * 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; - if (_DEBUG) warn('(bunyan: cleanupAndExit)'); + exiting = true; + _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.on('exit', function (pagerCode) { - if (_DEBUG) - warn('(bunyan: pager exit -> process.exit(%s))', - pagerCode || code); + pager.removeListener('exit', onPrematurePagerExit); + pager.on('exit', function onPagerExit(pagerCode) { + _selfTrace('pager exit -> process.exit(%s)', pagerCode || code); process.exit(pagerCode || code); }); - } else { - if (_DEBUG) warn('(bunyan: process.exit(%s))', code); + stdout.end(); + } 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; - - // 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); - }); + pager.on('exit', onPrematurePagerExit); } // Stdout error handling. (Couldn't setup until `stdout` was determined.) stdout.on('error', function (err) { - if (_DEBUG) warn('(stdout error event: %s)', err); - if (err.code === 'EPIPE') { - drainStdoutAndExit(0); - } else if (err.toString() === 'Error: This socket is closed.') { - // Could get this if the pager closes its stdin, but hasn't - // exited yet. - drainStdoutAndExit(1); + _selfTrace('stdout error event: %s, exiting=%s', err, exiting); + if (exiting) { + return; + } else if (err.code === 'EPIPE') { + cleanupAndExit(0); } else { - warn(err); - drainStdoutAndExit(1); + warn('bunyan: error on output stream: %s', err); + 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 { diff --git a/package.json b/package.json index 9b31ef9..b08e2b7 100644 --- a/package.json +++ b/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": { } }