CLI file args: bunyan foo.log bar.log

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
 

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
+The hack is that `, true`. It is a small bunyan performance hack by which you
-you're just adding simple fields to the child logger. This makes `log.child`
+can assert that you're just adding simple fields to the child logger -- i.e.
-10x faster and, hence, never a worry for slowing down HTTP request handling.
+not special fields like "level", "serializers", "streams". This makes
-See the changelog for node-bunyan 0.3.0 for details.
+`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
+The **source file, line and function of the log call site** can be added to
-be added to log records by using the `src: true` config option:
+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
+General level usage suggestions: "debug" should be used sparingly.
-errors *post mortem* should usually be included in "info" messages if it's
+Information that will be useful to debug errors *post mortem* should usually
-generally relevant or else with the corresponding "error" event. Don't rely on
+be included in "info" messages if it's generally relevant or else with the
-spewing mostly irrelevant debug messages all the time and sifting through them
+corresponding "error" event. Don't rely on spewing mostly irrelevant debug
-when an error occurs.
+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.
 

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 <https://github.com/trentm/json> for more complete docs.");
+  util.puts("See <https://github.com/trentm/node-bunyan> 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:
     // <http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/SimpleLayout.html>
-    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
+ * Process all input from stdin.
-
+ *
-function main(argv) {
+ * @params opts {Object} Bunyan options object.
-  var opts;
+ * @param stylize {Function} Output stylize function to use.
-  try {
+ * @param callback {Function} `function ()`
-    opts = parseArgv(argv);
+ */
-  } catch (e) {
+function processStdin(opts, stylize, callback) {
-    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);
-
   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 <https://github.com/trentm/json/issues/24>.
   // 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
+  // in node core. Node v0.6.9 fixes that. Only guard for v0.6.0..v0.6.8.
-  // 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;

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();
+    }
+  );
+});