diff --git a/CHANGES.md b/CHANGES.md index 0f7b65e..62b0c78 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -2,7 +2,12 @@ ## bunyan 0.6.6 (not yet released) -(nothing yet) +- Add support to the `bunyan` CLI taking log file path args, `bunyan foo.log`, + in addition to the usual `cat foo.log | bunyan`. +- Improve reliability of the default output formatting of the `bunyan` CLI. + Before it could blow up processing log records missing some expected + fields. + ## bunyan 0.6.5 diff --git a/README.md b/README.md index b4747d1..05854c0 100644 --- a/README.md +++ b/README.md @@ -118,7 +118,7 @@ same config as its parent, plus include the "component" field. wuzzle.woos(); log.info("done with the wuzzle") -* * * +### A little log.child hack. An example and a hack: The [node-restify](https://github.com/mcavage/node-restify) framework integrates bunyan. One feature is that each restify request handler @@ -129,12 +129,12 @@ includes a `req.log` logger that is: Apps using restify can then use `req.log` and have all such log records include the unique request id (as "req_id"). Handy. -*What is that `true`?* It is a small bunyan hack by which you can assert that -you're just adding simple fields to the child logger. This makes `log.child` -10x faster and, hence, never a worry for slowing down HTTP request handling. -See the changelog for node-bunyan 0.3.0 for details. +The hack is that `, true`. It is a small bunyan performance hack by which you +can assert that you're just adding simple fields to the child logger -- i.e. +not special fields like "level", "serializers", "streams". This makes +`log.child` 10x faster and, hence, never a worry for slowing down HTTP +request handling. See the changelog for node-bunyan 0.3.0 for details. -* * * ## serializers @@ -181,8 +181,8 @@ in your log record will be replaced with a short error message.* ## src -The **call source file, line and function** (if not at the global level) can -be added to log records by using the `src: true` config option: +The **source file, line and function of the log call site** can be added to +log records by using the `src: true` config option: var log = new Logger({src: true, ...}); @@ -209,6 +209,8 @@ in production.** # Levels +The log levels in bunyan are: + - "fatal" (60): the service/app is going to stop or become unusable now - "error" (50): fatal for a particular request, but the service/app continues servicing other requests - "warn" (40): a note on something that should probably be looked at by an operator @@ -216,13 +218,13 @@ in production.** - "debug" (20): anything else, i.e. too verbose to be included in "info" level. - "trace" (10): logging from external libraries used by your app -"debug" should be used sparingly. Information that will be useful to debug -errors *post mortem* should usually be included in "info" messages if it's -generally relevant or else with the corresponding "error" event. Don't rely on -spewing mostly irrelevant debug messages all the time and sifting through them -when an error occurs. +General level usage suggestions: "debug" should be used sparingly. +Information that will be useful to debug errors *post mortem* should usually +be included in "info" messages if it's generally relevant or else with the +corresponding "error" event. Don't rely on spewing mostly irrelevant debug +messages all the time and sifting through them when an error occurs. -Integers are used for the actual level values (1 for "trace", ..., 6 for +Integers are used for the actual level values (10 for "trace", ..., 60 for "fatal") and constants are defined for the (Logger.TRACE ... Logger.DEBUG). The lowercase level names are aliases supported in the API. diff --git a/bin/bunyan b/bin/bunyan index baf461c..ab6928a 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -11,6 +11,7 @@ var util = require('util'); var pathlib = require('path'); var vm = require('vm'); var http = require('http'); +var fs = require('fs'); var warn = console.warn; @@ -126,7 +127,7 @@ function objCopy(obj) { function printHelp() { util.puts("Usage:"); - util.puts(" cat some-json-log-file.log | bunyan [OPTIONS]"); + util.puts(" bunyan [OPTIONS] [FILE ...]"); util.puts(""); util.puts("Pipe in your JSON log file content (e.g. bunyan logs) for nicer "); util.puts("output"); @@ -146,7 +147,7 @@ function printHelp() { util.puts(" inspect: node.js `util.inspect` output"); util.puts(" -j shortcut for `-o json`"); util.puts(""); - util.puts("See for more complete docs."); + util.puts("See for more complete docs."); } @@ -273,6 +274,8 @@ var colors = { }; function stylizeWithColor(str, color) { + if (!str) + return ''; var codes = colors[color]; if (codes) { return '\033[' + codes[0] + 'm' + str + @@ -287,6 +290,25 @@ function stylizeWithoutColor(str, color) { } +/** + * Is this a valid Bunyna log record. + */ +function isValidRecord(rec) { + if (rec.v == null || + rec.level == null || + rec.name == null || + rec.hostname == null || + rec.pid == null || + rec.time == null || + rec.msg == null) { + // Not valid Bunyan log. + return false; + } else { + return true; + } +} + + /** * Print out a single result, considering input options. */ @@ -316,6 +338,10 @@ function handleLogLine(line, opts, stylize) { // If 'req', show the request. // If 'res', show the response. // If 'err' and 'err.stack' then show that. + if (!isValidRecord(rec)) { + return emit(line + '\n'); + } + delete rec.v; var time = stylize('[' + rec.time + ']', 'XXX'); @@ -477,7 +503,10 @@ function handleLogLine(line, opts, stylize) { case OM_SIMPLE: // - emit(format("%s - %s", upperNameFromLevel[rec.level] || "LVL" + rec.level, + if (!isValidRecord(rec)) { + return emit(line + '\n'); + } + emit(format("%s - %s\n", upperNameFromLevel[rec.level] || "LVL" + rec.level, rec.msg)); break; default: @@ -527,30 +556,17 @@ function drainStdoutAndExit(code) { } - -//---- mainline - -function main(argv) { - var opts; - try { - opts = parseArgv(argv); - } catch (e) { - warn("json: error: %s", e.message) - return drainStdoutAndExit(1); - } - //warn(opts); - if (opts.help) { - printHelp(); - return; - } - if (opts.version) { - util.puts("bunyan " + getVersion()); - return; - } - var stylize = (opts.color ? stylizeWithColor : stylizeWithoutColor); - +/** + * Process all input from stdin. + * + * @params opts {Object} Bunyan options object. + * @param stylize {Function} Output stylize function to use. + * @param callback {Function} `function ()` + */ +function processStdin(opts, stylize, callback) { var leftover = ""; // Left-over partial line from last chunk. - var stdin = process.openStdin(); + var stdin = process.stdin; + stdin.resume(); stdin.setEncoding('utf8'); stdin.on('data', function (chunk) { var lines = chunk.split(/\r\n|\n/); @@ -569,21 +585,144 @@ function main(argv) { handleLogLine(lines[i], opts, stylize); } }); - stdin.on('end', function () { if (leftover) { handleLogLine(leftover, opts, stylize); leftover = ''; } + callback(); }); } + +/** + * Process all input from the given log file. + * + * @param file {String} Log file path to process. + * @params opts {Object} Bunyan options object. + * @param stylize {Function} Output stylize function to use. + * @param callback {Function} `function ()` + */ +function processFile(file, opts, stylize, callback) { + var stream = fs.createReadStream(file, {encoding: 'utf8'}); + + stream.on('error', function (err) { + callback(err); + }) + + var leftover = ''; // Left-over partial line from last chunk. + stream.on('data', function (chunk) { + var lines = chunk.split(/\r\n|\n/); + var length = lines.length; + if (length === 1) { + leftover += lines[0]; + return; + } + + if (length > 1) { + handleLogLine(leftover + lines[0], opts, stylize); + } + leftover = lines.pop(); + length -= 1; + for (var i=1; i < length; i++) { + handleLogLine(lines[i], opts, stylize); + } + }); + + stream.on('end', function () { + if (leftover) { + handleLogLine(leftover, opts, stylize); + leftover = ''; + } + callback(); + }); +} + + +/** + * From node async module. + */ +function asyncForEachSeries(arr, iterator, callback) { + if (!arr.length) { + return callback(); + } + var completed = 0; + var iterate = function () { + iterator(arr[completed], function (err) { + if (err) { + callback(err); + callback = function () {}; + } + else { + completed += 1; + if (completed === arr.length) { + callback(); + } + else { + iterate(); + } + } + }); + }; + iterate(); +}; + + + +//---- mainline + +function main(argv) { + var opts; + try { + opts = parseArgv(argv); + } catch (e) { + warn("bunyan: error: %s", e.message) + return drainStdoutAndExit(1); + } + if (opts.help) { + printHelp(); + return; + } + if (opts.version) { + util.puts("bunyan " + getVersion()); + return; + } + var stylize = (opts.color ? stylizeWithColor : stylizeWithoutColor); + + var retval = 0; + if (opts.args.length > 0) { + var files = opts.args; + var i = 0; + asyncForEachSeries(files, + function (file, next) { + processFile(file, opts, stylize, function (err) { + if (err) { + warn('bunyan: %s', err.message); + retval += 1; + } + next(); + }); + }, + function (err) { + if (err) { + warn("bunyan: unexpected error: %s", err.stack || err); + return drainStdoutAndExit(1); + } + process.exit(retval); + } + ); + } else { + processStdin(opts, stylize, function () { + process.exit(retval); + }) + } +} + if (require.main === module) { // HACK guard for . // We override the `process.stdout.end` guard that core node.js puts in // place. The real fix is that `.end()` shouldn't be called on stdout - // in node core. Hopefully node v0.6.9 will fix that. Only guard - // for v0.6.0..v0.6.8. + // in node core. Node v0.6.9 fixes that. Only guard for v0.6.0..v0.6.8. var nodeVer = process.versions.node.split('.').map(Number); if ([0,6,0] <= nodeVer && nodeVer <= [0,6,8]) { var stdout = process.stdout; diff --git a/test/cli.test.js b/test/cli.test.js new file mode 100644 index 0000000..e8f21d3 --- /dev/null +++ b/test/cli.test.js @@ -0,0 +1,130 @@ +/* + * Copyright (c) 2012 Trent Mick. All rights reserved. + * + * Test the `bunyan` CLI. + */ + +var path = require('path'); +var exec = require('child_process').exec; +var format = require('util').format; +var test = require('tap').test; +var debug = console.warn; + +var BUNYAN = path.resolve(__dirname, '../bin/bunyan'); + +//child = exec('cat *.js bad_file | wc -l', +// function (error, stdout, stderr) { +// console.log('stdout: ' + stdout); +// console.log('stderr: ' + stderr); +// if (error !== null) { +// console.log('exec error: ' + error); +// } +//}); + +test('--version', function (t) { + var version = require('../package.json').version; + exec(BUNYAN + ' --version', function (err, stdout, stderr) { + t.error(err) + t.equal(stdout, 'bunyan ' + version + '\n'); + t.end(); + }); +}); + +test('--help', function (t) { + exec(BUNYAN + ' --help', function (err, stdout, stderr) { + t.error(err) + t.ok(stdout.indexOf('Options:') !== -1); + t.end(); + }); +}); + +test('-h', function (t) { + exec(BUNYAN + ' -h', function (err, stdout, stderr) { + t.error(err) + t.ok(stdout.indexOf('Options:') !== -1); + t.end(); + }); +}); + +test('--bogus', function (t) { + exec(BUNYAN + ' --bogus', function (err, stdout, stderr) { + t.ok(err, 'should error out') + t.equal(err.code, 1, '... with exit code 1') + t.end(); + }); +}); + +test('simple.log', function (t) { + exec(BUNYAN + ' corpus/simple.log', function (err, stdout, stderr) { + t.error(err) + t.equal(stdout, '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message\n'); + t.end(); + }); +}); +test('cat simple.log', function (t) { + exec(format('cat corpus/simple.log | %s', BUNYAN), + function (err, stdout, stderr) { + t.error(err) + t.equal(stdout, '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message\n'); + t.end(); + } + ); +}); +test('simple.log with color', function (t) { + exec(BUNYAN + ' --color corpus/simple.log', function (err, stdout, stderr) { + t.error(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'); + t.end(); + }); +}); + +test('extrafield.log', function (t) { + exec(BUNYAN + ' corpus/extrafield.log', function (err, stdout, stderr) { + t.error(err) + t.equal(stdout, '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message (extra=field)\n'); + t.end(); + }); +}); +test('extrafield.log with color', function (t) { + exec(BUNYAN + ' --color corpus/extrafield.log', function (err, stdout, stderr) { + t.error(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\u001b[90m (extra=field)\u001b[39m\n'); + t.end(); + }); +}); + +test('bogus.log', function (t) { + exec(BUNYAN + ' corpus/bogus.log', function (err, stdout, stderr) { + t.error(err) + t.equal(stdout, 'not a JSON line\n{"hi": "there"}\n'); + t.end(); + }); +}); + +test('bogus.log -j', function (t) { + exec(BUNYAN + ' -j corpus/bogus.log', function (err, stdout, stderr) { + t.error(err) + t.equal(stdout, 'not a JSON line\n{\n "hi": "there"\n}\n'); + t.end(); + }); +}); + +test('all.log', function (t) { + exec(BUNYAN + ' corpus/all.log', function (err, stdout, stderr) { + // Just make sure don't blow up on this. + t.error(err) + t.end(); + }); +}); + +test('simple.log doesnotexist1.log doesnotexist2.log', function (t) { + exec(BUNYAN + ' corpus/simple.log doesnotexist1.log doesnotexist2.log', + function (err, stdout, stderr) { + t.ok(err) + t.equal(err.code, 2) + t.equal(stdout, '[2012-02-08T22:56:52.856Z] INFO: myservice/123 on example.com: My message\n'); + t.equal(stderr, "bunyan: ENOENT, no such file or directory 'doesnotexist1.log'\nbunyan: ENOENT, no such file or directory 'doesnotexist2.log'\n"); + t.end(); + } + ); +});