Merge pull request #154 from pfmooney/GH-87

Fix #87 - nuke vm.runInNewContext condition filtering

bin/bunyan

@@ -276,9 +276,16 @@ function filterRecord(rec, opts)
         return false;
     }
 
-    if (opts.conditions) {
+    if (opts.condFuncs) {
-        for (var i = 0; i < opts.conditions.length; i++) {
+        var recCopy = objCopy(rec);
-            var pass = opts.conditions[i].runInNewContext(rec);
+        for (var i = 0; i < opts.condFuncs.length; i++) {
+            var pass = opts.condFuncs[i].call(recCopy);
+            if (!pass)
+                return false;
+        }
+    } else if (opts.condVm) {
+        for (var i = 0; i < opts.condVm.length; i++) {
+            var pass = opts.condVm[i].runInNewContext(rec);
             if (!pass)
                 return false;
         }
@@ -348,6 +355,33 @@ function emitNextRecord(opts, stylize)
     }
 }
 
+/**
+ * Return a function for the given JS code that returns.
+ *
+ * If no 'return' in the given javascript snippet, then assume we are a single
+ * statement and wrap in 'return (...)'. This is for convenience for short
+ * '-c ...' snippets.
+ */
+function funcWithReturnFromSnippet(js) {
+    // auto-"return"
+    if (js.indexOf('return') === -1) {
+        if (js.substring(js.length - 1) === ';') {
+            js = js.substring(0, js.length - 1);
+        }
+        js = 'return (' + js + ')';
+    }
+
+    // Expose level definitions to condition func context
+    var varDefs = [];
+    Object.keys(upperNameFromLevel).forEach(function (lvl) {
+        varDefs.push(format('var %s = %d;',
+                upperNameFromLevel[lvl], lvl));
+    });
+    varDefs = varDefs.join('\n') + '\n';
+
+    return (new Function(varDefs + js));
+}
+
 /**
  * Parse the command-line options and arguments into an object.
  *
@@ -400,6 +434,7 @@ function parseArgv(argv) {
     }
     args = newArgs;
 
+    // Expose level definitions to condition vm context
     var condDefines = [];
     Object.keys(upperNameFromLevel).forEach(function (lvl) {
         condDefines.push(
@@ -495,40 +530,46 @@ function parseArgv(argv) {
             case '-c':
             case '--condition':
                 var condition = args.shift();
-                parsed.conditions = parsed.conditions || [];
+                if (Boolean(process.env.JSON_EXEC &&
-                var scriptName = 'bunyan-condition-'+parsed.conditions.length;
+                    process.env.JSON_EXEC === 'vm')) {
-                var code = condDefines + condition;
+                    parsed.condVm = parsed.condVm || [];
-                try {
+                    var scriptName = 'bunyan-condition-'+parsed.condVm.length;
-                    var script = vm.createScript(code, scriptName);
+                    var code = condDefines + condition;
-                } catch (compileErr) {
+                    var script;
-                    throw new Error(format('illegal CONDITION code: %s\n'
+                    try {
-                        + '  CONDITION script:\n'
+                        script = vm.createScript(code, scriptName);
-                        + '%s\n'
+                    } catch (complErr) {
-                        + '  Error:\n'
+                        throw new Error(format('illegal CONDITION code: %s\n'
-                        + '%s',
+                            + '  CONDITION script:\n'
-                        compileErr, indent(code), indent(compileErr.stack)));
+                            + '%s\n'
-                }
+                            + '  Error:\n'
+                            + '%s',
+                            complErr, indent(code), indent(complErr.stack)));
+                    }
 
-                // Ensure this is a reasonably safe CONDITION.
+                    // Ensure this is a reasonably safe CONDITION.
-                try {
+                    try {
-                    script.runInNewContext(minValidRecord);
+                        script.runInNewContext(minValidRecord);
-                } catch (condErr) {
+                    } catch (condErr) {
-                    throw new Error(format(
+                        throw new Error(format(
-                        /* JSSTYLED */
+                            /* JSSTYLED */
-                        'CONDITION code cannot safely filter a minimal Bunyan log record\n'
+                            'CONDITION code cannot safely filter a minimal Bunyan log record\n'
-                        + '  CONDITION script:\n'
+                            + '  CONDITION script:\n'
-                        + '%s\n'
+                            + '%s\n'
-                        + '  Minimal Bunyan log record:\n'
+                            + '  Minimal Bunyan log record:\n'
-                        + '%s\n'
+                            + '%s\n'
-                        + '  Filter error:\n'
+                            + '  Filter error:\n'
-                        + '%s',
+                            + '%s',
-                        indent(code),
+                            indent(code),
-                        indent(JSON.stringify(minValidRecord, null, 2)),
+                            indent(JSON.stringify(minValidRecord, null, 2)),
-                        indent(condErr.stack)
+                            indent(condErr.stack)
-                        ));
+                            ));
+                    }
+                    parsed.condVm.push(script);
+                } else  {
+                    parsed.condFuncs = parsed.condFuncs || [];
+                    parsed.condFuncs.push(funcWithReturnFromSnippet(condition));
                 }
-
-                parsed.conditions.push(script);
                 break;
             default: // arguments
                 if (!endOfOptions && arg.length > 0 && arg[0] === '-') {

examples/handle-fs-error.js

@@ -18,19 +18,24 @@ if (fs.statSync(FILENAME).mode & S_IWUSR) {
         fs.chmodSync(FILENAME, 0444);
 }
 
-console.warn('- Create logger.')
+console.warn('- Create logger.');
-var log = bunyan.createLogger({name: 'handle-fs-error', streams: [{path: FILENAME}]});
+var log = bunyan.createLogger({
+        name: 'handle-fs-error',
+        streams: [
+                  {path: FILENAME}
+        ]
+});
 
 log.on('error', function (err) {
         console.warn('- The logger emitted an error:', err);
 });
 
-console.warn('- Call log.info(...).')
+console.warn('- Call log.info(...).');
 log.info('info log message');
-console.warn('- Called log.info(...).')
+console.warn('- Called log.info(...).');
 
 setTimeout(function () {
-        console.warn('- Call log.warn(...).')
+        console.warn('- Call log.warn(...).');
         log.warn('warn log message');
-        console.warn('- Called log.warn(...).')
+        console.warn('- Called log.warn(...).');
 }, 1000);

test/cli.test.js

@@ -280,7 +280,7 @@ test('--level 40', function (t) {
     });
 });
 
-test('--condition "level === 10 && pid === 123"', function (t) {
+test('--condition "this.level === 10 && this.pid === 123"', function (t) {
     var expect = [
         '# levels\n',
         /* JSSTYLED */
@@ -292,14 +292,14 @@ test('--condition "level === 10 && pid === 123"', function (t) {
         'not a JSON line\n',
         '{"hi": "there"}\n'
     ].join('');
-    var cmd = _('%s -c "level === 10 && pid === 123" %s/corpus/all.log',
+    var cmd = _('%s -c "this.level === 10 && this.pid === 123"'
-        BUNYAN, __dirname);
+                + ' %s/corpus/all.log', BUNYAN, __dirname);
     exec(cmd, function (err, stdout, stderr) {
         t.ifError(err);
         t.equal(stdout, expect);
         var cmd = _(
-            '%s --condition "level === 10 && pid === 123" %s/corpus/all.log',
+            '%s --condition "this.level === 10 && this.pid === 123"'
-            BUNYAN, __dirname);
+            + ' %s/corpus/all.log', BUNYAN, __dirname);
         exec(cmd, function (err, stdout, stderr) {
             t.ifError(err);
             t.equal(stdout, expect);
@@ -308,13 +308,34 @@ test('--condition "level === 10 && pid === 123"', function (t) {
     });
 });
 
+test('--condition "this.level === TRACE', function (t) {
+    var expect = [
+        '# levels\n',
+        /* JSSTYLED */
+        '[2012-02-08T22:56:50.856Z] TRACE: myservice/123 on example.com: My message\n',
+        '\n',
+        '# extra fields\n',
+        '\n',
+        '# bogus\n',
+        'not a JSON line\n',
+        '{"hi": "there"}\n'
+    ].join('');
+    var cmd = _('%s -c "this.level === TRACE" %s/corpus/all.log',
+        BUNYAN, __dirname);
+    exec(cmd, function (err, stdout, stderr) {
+        t.ifError(err);
+        t.equal(stdout, expect);
+        t.done();
+    });
+});
+
 // multiple
 // not sure if this is a bug or a feature.  let's call it a feature!
 test('multiple --conditions', function (t) {
     var expect = [
         '# levels\n',
         /* JSSTYLED */
-        '[2012-02-08T22:56:53.856Z]  WARN: myservice/1 on example.com: My message\n',
+        '[2012-02-08T22:56:53.856Z]  WARN: myservice/123 on example.com: My message\n',
         '\n',
         '# extra fields\n',
         '\n',
@@ -322,10 +343,8 @@ test('multiple --conditions', function (t) {
         'not a JSON line\n',
         '{"hi": "there"}\n'
     ].join('');
-    exec(_('%s %s/corpus/all.log ' +
+    exec(_('%s %s/corpus/all.log -c "this.level === 40" -c "this.pid === 123"',
-                 '-c "if (level === 40) pid = 1; true" ' +
+            BUNYAN, __dirname), function (err, stdout, stderr) {
-                 '-c "pid === 1"', BUNYAN, __dirname),
-             function (err, stdout, stderr) {
         t.ifError(err);
         t.equal(stdout, expect);
         t.end();