bunyan CLI auto-paging

CHANGES.md

@@ -6,7 +6,22 @@ Known issues:
   bug](https://github.com/TooTallNate/node-gyp/issues/65).
 
 
-## bunyan 0.17.1 (not yet released)
+## bunyan 0.18.0 (not yet released)
+
+- Automatic paging support in the `bunyan` CLI (similar to `git log` et al).
+  IOW, `bunyan` will open your pager (by default `less`) and pipe rendered
+  log output through it. A main benefit of this is getting colored logs with
+  a pager without the pain. Before you had to explicit use `--color` to tell
+  bunyan to color output when the output was not a TTY:
+
+        bunyan foo.log --color | less -R        # before
+        bunyan foo.log                          # now
+
+  Disable with the `--no-pager` option or the `BUNYAN_NO_PAGER=1` environment
+  variable.
+
+  Limitations: Only supported for node >=0.8. Windows is not supported (at
+  least not yet).
 
 - Switch test suite to nodeunit (still using a node-tap'ish API via
   a helper).

TODO.md

@@ -1,12 +1,16 @@
 - man page for the bunyan CLI (refer to it in the readme)
-- full-on docs. The readme is too clunky now.
+- coloring bug: in less the indented extra info lines only have the first
-- paging
+  line colored. Do we need the ANSI char on *each* line? That'll be
+  slower.
 - `tail -f`-like support
 - 1.0 with `v: 1` in log records. Fwd/bwd compat in `bunyan` CLI
 
 
 # someday/maybe
 
+- full-on docs
+- better examples/
+- better coloring
 - "template" support for 'rotating-file' stream to get dated rolled files
 - "all" or "off" levels? log4j? logging.py?
   logging.py has NOTSET === 0. I think that is only needed/used for

bin/bunyan

@@ -5,7 +5,7 @@
 // See <https://github.com/trentm/node-bunyan>.
 //
 
-var VERSION = "0.17.1";
+var VERSION = "0.18.0";
 
 var util = require('util');
 var pathlib = require('path');
@@ -17,6 +17,7 @@ var child_process = require('child_process'),
   spawn = child_process.spawn,
   exec = child_process.exec,
   execFile = child_process.execFile;
+var assert = require('assert');
 
 var nodeSpawnSupportsStdio = (
   Number(process.version.split('.')[0]) >= 0
@@ -26,6 +27,9 @@ var nodeSpawnSupportsStdio = (
 
 //---- globals and constants
 
+// Internal debug logging via `console.warn`.
+var _DEBUG = false;
+
 // Output modes.
 var OM_PAUL = 1;
 var OM_JSON = 2;
@@ -81,6 +85,10 @@ var usingAnsiCodes = false;
 // Global ref to options used only by 'uncaughtException' handler.
 var gOptsForUncaughtException;
 
+// Pager child process, and output stream to which to write.
+var pager = null;
+var stdout = process.stdout;
+
 
 
 //---- support functions
@@ -185,6 +193,10 @@ function printHelp() {
   console.log("                non-JSON, and non-Bunyan lines are passed through.");
   console.log("");
   console.log("Output options:");
+  console.log("  --pager       Pipe output into `less` (or $PAGER if set), if");
+  console.log("                stdout is a terminal. This overrides $BUNYAN_NO_PAGER.");
+  console.log("                Note: Paging is only supported on node >=0.8.");
+  console.log("  --no-pager    Do not pipe output into a pager.");
   console.log("  --color       Colorize output. Defaults to try if output");
   console.log("                stream is a TTY.");
   console.log("  --no-color    Force no coloring (e.g. terminal doesn't support it)");
@@ -212,6 +224,8 @@ function printHelp() {
   console.log("Environment Variables:");
   console.log("  BUNYAN_NO_COLOR    Set to a non-empty value to force no output ");
   console.log("                     coloring. See '--no-color'.");
+  console.log("  BUNYAN_NO_PAGER    Disable piping output to a pager. ");
+  console.log("                     See '--no-pager'.");
   console.log("");
   console.log("See <https://github.com/trentm/node-bunyan> for more complete docs.");
   console.log("Please report bugs to <https://github.com/trentm/node-bunyan/issues>.");
@@ -337,6 +351,7 @@ function parseArgv(argv) {
     args: [],
     help: false,
     color: null,
+    paginate: null,
     outputMode: OM_PAUL,
     jsonIndent: 2,
     level: null,
@@ -399,6 +414,12 @@ function parseArgv(argv) {
       case "--no-color":
         parsed.color = false;
         break;
+      case "--pager":
+        parsed.paginate = true;
+        break;
+      case "--no-pager":
+        parsed.paginate = false;
+        break;
       case "-o":
       case "--output":
         var name = args.shift();
@@ -893,25 +914,13 @@ function emitRecord(rec, line, opts, stylize) {
 
 var stdoutFlushed = true;
 function emit(s) {
-  // TODO:PERF If this is try/catch is too slow (too granular): move up to
-  //    mainline and be sure to only catch this particular error.
   try {
-    stdoutFlushed = process.stdout.write(s);
+    stdoutFlushed = stdout.write(s);
   } catch (e) {
-    // Handle any exceptions in stdout writing in the "error" event above.
+    // Handle any exceptions in stdout writing in `stdout.on("error", ...)`.
   }
 }
 
-process.stdout.on("error", function (err) {
-  if (err.code === "EPIPE") {
-    // Pass. See <https://github.com/trentm/json/issues/9>.
-    drainStdoutAndExit(0);
-  } else {
-    warn(err);
-    drainStdoutAndExit(1);
-  }
-});
-
 
 /**
  * A hacked up version of "process.exit" that will first drain stdout
@@ -924,11 +933,12 @@ process.stdout.on("error", function (err) {
  * still be necessary in a shell pipeline.
  */
 function drainStdoutAndExit(code) {
-  process.stdout.on('drain', function () {
+  if (_DEBUG) warn('(drainStdoutAndExit(%d))', code);
-    process.exit(code);
+  stdout.on('drain', function () {
+    cleanupAndExit(code);
   });
   if (stdoutFlushed) {
-    process.exit(code);
+    cleanupAndExit(code);
   }
 }
 
@@ -1189,24 +1199,58 @@ function asyncForEach(arr, iterator, callback) {
 
 
 
-//---- mainline
+/**
-
+ * Cleanup and exit properly.
-// Try to ensure we close a child 'dtrace' process on signalled exit.
+ *
-function signalCleanupAndExit(signal) {
+ * Warning: this doesn't stop processing, i.e. process exit might be delayed.
-  if (usingAnsiCodes) {
+ * It is up to the caller to ensure that no subsequent bunyan processing
-    // Clear possibly interrupted ANSI code (issue #59).
+ * is done after calling this.
-    process.stdout.write('\033[0m');
+ *
+ * @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) {
+    return;
   }
+  cleanedUp = true;
+  if (_DEBUG) warn('(bunyan: cleanupAndExit)');
+
+  // Clear possibly interrupted ANSI code (issue #59).
+  if (usingAnsiCodes) {
+    stdout.write('\033[0m');
+  }
+
+  // Kill possible dtrace child.
   if (child) {
     child.kill(signal);
   }
-  process.exit();
-}
-process.on('SIGINT', function () { signalCleanupAndExit('SIGINT'); });
-process.on('SIGQUIT', function () { signalCleanupAndExit('SIGQUIT'); });
-process.on('SIGTERM', function () { signalCleanupAndExit('SIGTERM'); });
-process.on('SIGHUP', function () { signalCleanupAndExit('SIGHUP'); });
 
+  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);
+      process.exit(pagerCode || code);
+    });
+  } else {
+    if (_DEBUG) warn('(bunyan: process.exit(%s))', code);
+    process.exit(code);
+  }
+}
+
+
+
+//---- mainline
+
+process.on('SIGINT', function () { cleanupAndExit(1, 'SIGINT'); });
+process.on('SIGQUIT', function () { cleanupAndExit(1, 'SIGQUIT'); });
+process.on('SIGTERM', function () { cleanupAndExit(1, 'SIGTERM'); });
+process.on('SIGHUP', function () { cleanupAndExit(1, 'SIGHUP'); });
 
 process.on('uncaughtException', function (err) {
   function _indent(s) {
@@ -1243,6 +1287,7 @@ process.on('uncaughtException', function (err) {
   process.exit(1);
 });
 
+
 function main(argv) {
   try {
     var opts = parseArgv(argv);
@@ -1275,10 +1320,65 @@ function main(argv) {
   usingAnsiCodes = opts.color; // intentionally global
   var stylize = (opts.color ? stylizeWithColor : stylizeWithoutColor);
 
+  // Pager.
+  var nodeVer = process.versions.node.split('.').map(Number);
+  var paginate = (process.stdout.isTTY
+                  && process.platform !== 'win32'
+                  && nodeVer >= [0,8,0]
+                  && (opts.paginate === true
+                      || (opts.paginate !== false
+                          && (!process.env.BUNYAN_NO_PAGER
+                              || process.env.BUNYAN_NO_PAGER.length === 0))));
+  if (paginate) {
+    var pagerCmd = process.env.PAGER || 'less';
+    assert.ok(pagerCmd.indexOf('"') === -1 && pagerCmd.indexOf("'") === -1,
+      'cannot parse PAGER quotes yet');
+    var argv = pagerCmd.split(/\s+/g);
+    var env = objCopy(process.env);
+    if (env.LESS === undefined) {
+      // git's default is LESS=FRSX. I don't like the 'S' here because lines
+      // are *typically* wide with bunyan output and scrolling horizontally
+      // is a royal pain.
+      // Note a bug in Mac's `less -F`, such that SIGWINCH can kill it.
+      // If that rears too much then I'll remove 'F' from here.
+      env.LESS = 'FRX';
+    }
+    if (_DEBUG) warn("(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);
+    });
+  }
+
+  // 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);
+    } else {
+      warn(err);
+      drainStdoutAndExit(1);
+    }
+  });
+
   var retval = 0;
   if (opts.pids) {
     processPids(opts, stylize, function (code) {
-      process.exit(code);
+      cleanupAndExit(code);
     });
   } else if (opts.args.length > 0) {
     var files = opts.args;
@@ -1300,12 +1400,12 @@ function main(argv) {
           warn("bunyan: unexpected error: %s", err.stack || err);
           return drainStdoutAndExit(1);
         }
-        process.exit(retval);
+        cleanupAndExit(retval);
       }
     );
   } else {
     processStdin(opts, stylize, function () {
-      process.exit(retval);
+      cleanupAndExit(retval);
     });
   }
 }

examples/long-running.js

@@ -0,0 +1,58 @@
+/*
+ * A long-running process that does some periodic logging. Use bunyan with
+ * it some of these ways:
+ *
+ * 1. Direct piping:
+ *        node long-running.js | bunyan
+ * 2. Logging to file (e.g. if run via a service system like upstart or
+ *    illumos' SMF that sends std output to a log file), then tail -f that
+ *    log file.
+ *        node long-running.js > long-running.log 2>&1
+ *        tail -f long-running.log | bunyan
+ * 3. Dtrace to watch the logging. This has the bonus of being able to watch
+ *    all log levels... even if not normally emitted.
+ *        node long-running.js > long-running.log 2>&1
+ *        bunyan -p $(head -1 long-running.log | json pid)
+ *
+ */
+
+var fs = require('fs');
+var bunyan = require('../lib/bunyan');
+
+
+function randint(n) {
+  return Math.floor(Math.random() * n);
+}
+
+function randchoice(array) {
+  return array[randint(array.length)];
+}
+
+
+//---- mainline
+
+var words = fs.readFileSync(__dirname + '/long-running.js', 'utf8').split(/\s+/);
+var levels = ['trace', 'debug', 'info', 'warn', 'error', 'fatal'];
+var timeout;
+
+var log = bunyan.createLogger({name: 'lr', level: 'debug'});
+
+// We're logging to stdout. Let's exit gracefully on EPIPE. E.g. if piped
+// to `head` which will close after N lines.
+process.stdout.on('error', function (err) {
+  if (err.code === 'EPIPE') {
+    process.exit(0);
+  }
+})
+
+function logOne() {
+  var level = randchoice(levels);
+  var msg = [randchoice(words), randchoice(words)].join(' ');
+  var delay = randint(300);
+  //console.warn('long-running about to log.%s(..., "%s")', level, msg)
+  log[level]({"word": randchoice(words), "delay": delay}, msg);
+  timeout = setTimeout(logOne, delay);
+}
+
+log.info('hi, this is the start');
+timeout = setTimeout(logOne, 1000);

lib/bunyan.js

@@ -4,7 +4,7 @@
  * The bunyan logging library for node.js.
  */
 
-var VERSION = '0.17.1';
+var VERSION = '0.18.0';
 
 // Bunyan log format version. This becomes the 'v' field on all log records.
 // `0` is until I release a version '1.0.0' of node-bunyan. Thereafter,

package.json

@@ -1,6 +1,6 @@
 {
   "name": "bunyan",
-  "version": "0.17.1",
+  "version": "0.18.0",
   "description": "a JSON Logger library for node.js services",
   "author": "Trent Mick <trentm@gmail.com> (http://trentm.com)",
   "main": "./lib/bunyan.js",

test/cli.test.js

@@ -90,7 +90,7 @@ test('simple.log with color', function (t) {
     t.ifError(err)
     t.equal(stdout,
       '[2012-02-08T22:56:52.856Z] \u001b[36m INFO\u001b[39m: myservice/123 '
-      + 'on example.com: \u001b[36mMy message\u001b[39m\n');
+      + 'on example.com: \u001b[36mMy message\u001b[39m\n\u001b[0m');
     t.end();
   });
 });
@@ -112,7 +112,7 @@ test('extrafield.log with color', function (t) {
     t.equal(stdout,
       '[2012-02-08T22:56:52.856Z] \u001b[36m INFO\u001b[39m: myservice/123 '
       + 'on example.com: \u001b[36mMy message\u001b[39m'
-      + '\u001b[90m (extra=field)\u001b[39m\n');
+      + '\u001b[90m (extra=field)\u001b[39m\n\u001b[0m');
     t.end();
   });
 });