guards and UX for -c CONDITION usage

CHANGES.md

@@ -8,7 +8,73 @@ Known issues:
 
 ## bunyan 0.16.8 (not yet released)
 
-(nothing yet)
+- Guards on `-c CONDITION` usage to attempt to be more user friendly.
+  Bogus JS code will result in this:
+
+        $ bunyan portal.log -c 'this.req.username==boo@foo'
+        bunyan: error: illegal CONDITION code: SyntaxError: Unexpected token ILLEGAL
+          CONDITION script:
+            Object.prototype.TRACE = 10;
+            Object.prototype.DEBUG = 20;
+            Object.prototype.INFO = 30;
+            Object.prototype.WARN = 40;
+            Object.prototype.ERROR = 50;
+            Object.prototype.FATAL = 60;
+            this.req.username==boo@foo
+          Error:
+            SyntaxError: Unexpected token ILLEGAL
+                at new Script (vm.js:32:12)
+                at Function.Script.createScript (vm.js:48:10)
+                at parseArgv (/Users/trentm/tm/node-bunyan-0.x/bin/bunyan:465:27)
+                at main (/Users/trentm/tm/node-bunyan-0.x/bin/bunyan:1252:16)
+                at Object.<anonymous> (/Users/trentm/tm/node-bunyan-0.x/bin/bunyan:1330:3)
+                at Module._compile (module.js:449:26)
+                at Object.Module._extensions..js (module.js:467:10)
+                at Module.load (module.js:356:32)
+                at Function.Module._load (module.js:312:12)
+                at Module.runMain (module.js:492:10)
+
+  And all CONDITION scripts will be run against a minimal valid Bunyan
+  log record to ensure they properly guard against undefined values
+  (at least as much as can reasonably be checked). For example:
+
+        $ bunyan portal.log -c 'this.req.username=="bob"'
+        bunyan: error: CONDITION code cannot safely filter a minimal Bunyan log record
+          CONDITION script:
+            Object.prototype.TRACE = 10;
+            Object.prototype.DEBUG = 20;
+            Object.prototype.INFO = 30;
+            Object.prototype.WARN = 40;
+            Object.prototype.ERROR = 50;
+            Object.prototype.FATAL = 60;
+            this.req.username=="bob"
+          Minimal Bunyan log record:
+            {
+              "v": 0,
+              "level": 30,
+              "name": "name",
+              "hostname": "hostname",
+              "pid": 123,
+              "time": 1355514346206,
+              "msg": "msg"
+            }
+          Filter error:
+            TypeError: Cannot read property 'username' of undefined
+                at bunyan-condition-0:7:9
+                at Script.Object.keys.forEach.(anonymous function) [as runInNewContext] (vm.js:41:22)
+                at parseArgv (/Users/trentm/tm/node-bunyan-0.x/bin/bunyan:477:18)
+                at main (/Users/trentm/tm/node-bunyan-0.x/bin/bunyan:1252:16)
+                at Object.<anonymous> (/Users/trentm/tm/node-bunyan-0.x/bin/bunyan:1330:3)
+                at Module._compile (module.js:449:26)
+                at Object.Module._extensions..js (module.js:467:10)
+                at Module.load (module.js:356:32)
+                at Function.Module._load (module.js:312:12)
+                at Module.runMain (module.js:492:10)
+
+  A proper way to do that condition would be:
+
+        $ bunyan portal.log -c 'this.req && this.req.username=="bob"'
+
 
 
 ## bunyan 0.16.7

README.md

@@ -73,10 +73,10 @@ collisions.
 
 ## bunyan tool
 
-A `bunyan` tool is provided **for pretty-printing bunyan logs** and, eventually,
+A `bunyan` tool is provided **for pretty-printing bunyan logs** and for
-for filtering (e.g. `| bunyan -c 'level>3'`). This shows the default output
+**filtering** (e.g. `| bunyan -c 'this.foo == "bar"'`). This shows the default
-(which is fluid right now) and indented-JSON output. More output formats will
+output and indented-JSON output. More output formats will be added, including
-be added, including support for custom formats.
+support for custom formats.
 
     $ node hi.js | ./bin/bunyan  # CLI tool to filter/pretty-print JSON logs.
     [2012-01-31T00:08:11.387Z] INFO: myapp on banana.local/123: hi

bin/bunyan

@@ -18,7 +18,9 @@ var child_process = require('child_process'),
   exec = child_process.exec,
   execFile = child_process.execFile;
 
-var nodeSpawnSupportsStdio = (Number(process.version.split('.')[1]) >= 8);
+var nodeSpawnSupportsStdio = (
+  Number(process.version.split('.')[0]) >= 0
+  || Number(process.version.split('.')[1]) >= 8);
 
 
 
@@ -76,6 +78,9 @@ var child = null;
 // Whether ANSI codes are being used. Used for signal-handling.
 var usingAnsiCodes = false;
 
+// Global ref to options used only by 'uncaughtException' handler.
+var gOptsForUncaughtException;
+
 
 
 //---- support functions
@@ -168,10 +173,14 @@ function printHelp() {
   console.log("                You can specify level *names* or numeric values.");
   console.log("                (See 'Log Levels' below.)");
   console.log("  -c, --condition CONDITION");
-  console.log("                Run each log message through the condition");
+  console.log("                Run each log message through the condition and");
-  console.log("                and only show those that resolve to a truish value.");
+  console.log("                only show those that return truish. E.g.:");
-  console.log("                E.g. `-c 'pid == 123'`, `-c 'level == 50'`. You must");
+  console.log("                    -c 'this.pid == 123'");
-  console.log("                use the numeric values for filtering by level.");
+  console.log("                    -c 'this.level == DEBUG'");
+  console.log("                    -c 'this.msg.indexOf(\"boom\") != -1'");
+  console.log("                'CONDITION' must be legal JS code. `this` holds");
+  console.log("                the log record. The TRACE, DEBUG, ... FATAL values");
+  console.log("                are defined to help with comparing `this.level`.");
   console.log("  --strict      Suppress all but legal Bunyan JSON log lines. By default");
   console.log("                non-JSON, and non-Bunyan lines are passed through.");
   console.log("");
@@ -395,9 +404,9 @@ function parseArgv(argv) {
         var name = args.shift();
         var idx = name.lastIndexOf('-');
         if (idx !== -1) {
-          var indent = Number(name.slice(idx+1));
+          var indentation = Number(name.slice(idx+1));
-          if (! isNaN(indent)) {
+          if (! isNaN(indentation)) {
-            parsed.jsonIndent = indent;
+            parsed.jsonIndent = indentation;
             name = name.slice(0, idx);
           }
         }
@@ -451,7 +460,36 @@ function parseArgv(argv) {
         var condition = args.shift();
         parsed.conditions = parsed.conditions || [];
         var scriptName = 'bunyan-condition-'+parsed.conditions.length;
-        var script = vm.createScript(condDefines + condition, scriptName);
+        var code = condDefines + condition;
+        try {
+          var script = vm.createScript(code, scriptName);
+        } catch (compileErr) {
+          throw new Error(format('illegal CONDITION code: %s\n'
+            + '  CONDITION script:\n'
+            + '%s\n'
+            + '  Error:\n'
+            + '%s',
+            compileErr, indent(code), indent(compileErr.stack)));
+        }
+
+        // Ensure this is a reasonably safe CONDITION.
+        try {
+          script.runInNewContext(minValidRecord);
+        } catch (condErr) {
+          throw new Error(format(
+            'CONDITION code cannot safely filter a minimal Bunyan log record\n'
+            + '  CONDITION script:\n'
+            + '%s\n'
+            + '  Minimal Bunyan log record:\n'
+            + '%s\n'
+            + '  Filter error:\n'
+            + '%s',
+            indent(code),
+            indent(JSON.stringify(minValidRecord, null, 2)),
+            indent(condErr.stack)
+            ));
+        }
+
         parsed.conditions.push(script);
         break;
       default: // arguments
@@ -527,6 +565,15 @@ function isValidRecord(rec) {
     return true;
   }
 }
+var minValidRecord = {
+  v: 0,   //TODO: get this from bunyan.LOG_VERSION
+  level: INFO,
+  name: 'name',
+  hostname: 'hostname',
+  pid: 123,
+  time: Date.now(),
+  msg: 'msg'
+};
 
 
 /**
@@ -1166,7 +1213,7 @@ process.on('SIGHUP', function () { signalCleanupAndExit('SIGHUP'); });
 
 
 process.on('uncaughtException', function (err) {
-  function indent(s) {
+  function _indent(s) {
     var lines = s.split(/\r?\n/);
     for (var i = 0; i < lines.length; i++) {
       lines[i] = '*     ' + lines[i];
@@ -1175,10 +1222,17 @@ process.on('uncaughtException', function (err) {
   }
 
   var title = encodeURIComponent(format(
-    "Bunyan %s crashed: %s", getVersion(), err.message));
+    "Bunyan %s crashed: %s", getVersion(), String(err)));
   console.error('* * *');
-  console.error('* The Bunyan CLI crashed! Please report this issue and');
+  console.error('* The Bunyan CLI crashed!');
-  console.error('* include the details below:');
+  console.error('*');
+  if (err.name === 'ReferenceError' && gOptsForUncaughtException.conditions) {
+    console.error('* A "ReferenceError" is often the result of given');
+    console.error('* `-c CONDITION` code that doesn\'t guard against undefined');
+    console.error('* values. If that is not the problem:');
+    console.error('*');
+  }
+  console.error('* Please report this issue and include the details below:');
   console.error('*');
   console.error('*    https://github.com/trentm/node-bunyan/issues/new?title=%s', title);
   console.error('*');
@@ -1188,19 +1242,19 @@ process.on('uncaughtException', function (err) {
   console.error('* argv: %j', process.argv);
   console.error('* log line: %j', currLine);
   console.error('* stack:');
-  console.error(indent(err.stack));
+  console.error(_indent(err.stack));
   console.error('* * *');
   process.exit(1);
 });
 
 function main(argv) {
-  var opts;
   try {
-    opts = parseArgv(argv);
+    var opts = parseArgv(argv);
   } catch (e) {
     warn("bunyan: error: %s", e.message);
     return drainStdoutAndExit(1);
   }
+  gOptsForUncaughtException = opts; // intentionally global
   if (opts.help) {
     printHelp();
     return;