From b1c143c87a25047299d8304485b4eb9f429a9bca Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Fri, 18 Jan 2013 16:27:53 -0800 Subject: [PATCH] bunyan CLI auto-paging --- CHANGES.md | 17 +++- TODO.md | 8 +- bin/bunyan | 168 +++++++++++++++++++++++++++++++-------- examples/long-running.js | 58 ++++++++++++++ lib/bunyan.js | 2 +- package.json | 2 +- test/cli.test.js | 4 +- 7 files changed, 218 insertions(+), 41 deletions(-) create mode 100644 examples/long-running.js diff --git a/CHANGES.md b/CHANGES.md index 37cf235..3640da2 100644 --- a/CHANGES.md +++ b/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). diff --git a/TODO.md b/TODO.md index b182de3..85f3495 100644 --- a/TODO.md +++ b/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. -- paging +- coloring bug: in less the indented extra info lines only have the first + 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 diff --git a/bin/bunyan b/bin/bunyan index 16e0dd3..818ebff 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -5,7 +5,7 @@ // See . // -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 for more complete docs."); console.log("Please report bugs to ."); @@ -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 . - 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 () { - process.exit(code); + if (_DEBUG) warn('(drainStdoutAndExit(%d))', code); + stdout.on('drain', function () { + cleanupAndExit(code); }); if (stdoutFlushed) { - process.exit(code); + cleanupAndExit(code); } } @@ -1189,24 +1199,58 @@ function asyncForEach(arr, iterator, callback) { -//---- mainline - -// Try to ensure we close a child 'dtrace' process on signalled exit. -function signalCleanupAndExit(signal) { - if (usingAnsiCodes) { - // Clear possibly interrupted ANSI code (issue #59). - process.stdout.write('\033[0m'); +/** + * 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. + * + * @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); }); } } diff --git a/examples/long-running.js b/examples/long-running.js new file mode 100644 index 0000000..7583aaf --- /dev/null +++ b/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); diff --git a/lib/bunyan.js b/lib/bunyan.js index 4a8cfda..a008ae3 100644 --- a/lib/bunyan.js +++ b/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, diff --git a/package.json b/package.json index c8a202e..10742cd 100644 --- a/package.json +++ b/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 (http://trentm.com)", "main": "./lib/bunyan.js", diff --git a/test/cli.test.js b/test/cli.test.js index 42f6a6f..fe68362 100644 --- a/test/cli.test.js +++ b/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(); }); });