Add support for log points

lib/debuglet.js

@@ -32,8 +32,8 @@ var assert = require('assert');
 
 var NODE_VERSION_MESSAGE = 'Node.js version not supported. Node.js 5.2.0 and ' +
   ' versions older than 0.12 are not supported.';
-var BREAKPOINT_ACTION_MESSAGE = 'The only currently supported breakpoint action' +
-  ' is CAPTURE.';
+var BREAKPOINT_ACTION_MESSAGE = 'The only currently supported breakpoint actions' +
+  ' are CAPTURE and LOG.';
 
 module.exports = Debuglet;
 
@@ -219,7 +219,7 @@ Debuglet.prototype.scheduleBreakpointFetch_ = function(seconds) {
           }
           var bps = (body.breakpoints || []).filter(function(bp) {
             var action = bp.action || 'CAPTURE';
-            if (action !== 'CAPTURE') {
+            if (action !== 'CAPTURE' && action !== 'LOG') {
               that.logger_.warn('Found breakpoint with invalid action:', action);
               bp.status = new StatusMessage(StatusMessage.UNSPECIFIED,
                 BREAKPOINT_ACTION_MESSAGE, true);
@@ -333,15 +333,28 @@ Debuglet.prototype.addBreakpoint_ = function(breakpoint, cb) {
     that.logger_.info('\tsuccessfully added breakpoint  ' + breakpoint.id);
     that.activeBreakpointMap_[breakpoint.id] = breakpoint;
 
-    that.v8debug_.wait(breakpoint, function(err) {
+    that.v8debug_.wait(breakpoint, function waitHandler(err) {
       if (err) {
         that.logger_.error(err);
         cb(err);
         return;
       }
 
       that.logger_.info('Breakpoint hit!: ' + breakpoint.id);
-      that.completeBreakpoint_(breakpoint);
+      if (breakpoint.action === 'LOG') {
+        var message = Debuglet.format(breakpoint.logMessageFormat,
+          breakpoint.evaluatedExpressions.map(function(v) {
+            return v.value;
+          }));
+        console.log(message);
+        if (!that.completedBreakpointMap_[breakpoint.id]) {
+          setTimeout(function() {
+            that.v8debug_.wait(breakpoint, waitHandler);
+          }, 500);
+        }
+      } else {
+        that.completeBreakpoint_(breakpoint);
+      }
     });
   });
 };
@@ -434,3 +447,53 @@ Debuglet.mapSubtract = function mapSubtract(A, B) {
   return removed;
 };
 
+/**
+ * Formats the message base with placeholders `$0`, `$1`, etc
+ * by substituting the provided expressions. If more expressions
+ * are given than placeholders extra expressions are dropped.
+ */
+Debuglet.format = function(base, exprs) {
+  var tokens = Debuglet._tokenize(base, exprs.length);
+  for (var i = 0; i < tokens.length; i++) {
+    if (!tokens[i].v) {
+      continue;
+    }
+    if (tokens[i].v === '$$') {
+      tokens[i] = '$';
+      continue;
+    }
+    for (var j = 0; j < exprs.length; j++) {
+      if (tokens[i].v === '$' + j) {
+        tokens[i] = exprs[j];
+        break;
+      }
+    }
+  }
+  return tokens.join('');
+};
+
+Debuglet._tokenize = function(base, exprLength) {
+  var acc = Debuglet._delimit(base, '$$');
+  for (var i = exprLength - 1; i >= 0; i--) {
+    var newAcc = [];
+    for (var j = 0; j < acc.length; j++) {
+      if (acc[j].v) {
+        newAcc.push(acc[j]);
+      } else {
+        newAcc.push.apply(newAcc, Debuglet._delimit(acc[j], '$' + i));
+      }
+    }
+    acc = newAcc;
+  }
+  return acc;
+};
+
+Debuglet._delimit = function(source, delim) {
+  var pieces = source.split(delim);
+  var dest = [];
+  dest.push(pieces[0]);
+  for (var i = 1; i < pieces.length; i++) {
+    dest.push({ v: delim }, pieces[i]);
+  }
+  return dest;
+};

lib/v8debugapi.js

@@ -23,6 +23,7 @@
 /** @const */ var state = require('./state.js');
 /** @const */ var logModule = require('@google/cloud-diagnostics-common').logger;
 /** @const */ var apiclasses = require('./apiclasses.js');
+/** @const */ var _ = require('lodash');
 /** @const */ var StatusMessage = apiclasses.StatusMessage;
 
 /** @const */ var messages = {
@@ -484,7 +485,14 @@ module.exports.create = function(logger_, config_, fileStats_) {
         }
       }
     }
-    var captured = state.capture(execState, breakpoint.expressions, config);
+    var localConfig;
+    if (breakpoint.action === 'LOG') {
+      localConfig = { capture: { maxFrames: 0 } };
+      _.defaultsDeep(localConfig, config);
+    } else {
+      localConfig = config;
+    }
+    var captured = state.capture(execState, breakpoint.expressions, localConfig);
     breakpoint.stackFrames = captured.stackFrames;
     breakpoint.variableTable = captured.variableTable;
     breakpoint.evaluatedExpressions =

test/e2e/test.js

@@ -36,6 +36,7 @@ var SCOPES = [
   ];
 
 var agent;
+var transcript = '';
 
 function apiRequest(authClient, url, method, body) {
   method = method || 'GET';
@@ -131,6 +132,45 @@ function runTest() {
         console.log('-- delete results', deleteResults);
         return debuggee;
       })
+      .then(function(debuggee) {
+        // Set a breakpoint
+        console.log('-- setting a logpoint');
+        var promise = setBreakpoint(debuggee, {
+          id: 'breakpoint-1',
+          location: {path: 'test.js', line: 5},
+          condition: 'n === 10',
+          action: 'LOG',
+          expressions: ['n'],
+          log_message_format: 'n is: $0'
+        });
+        // I don't know what I am doing. There is a better way to write the
+        // following using promises.
+        var result = promise.then(function(body) {
+          console.log('-- resolution of setBreakpoint', body);
+          assert.ok(body.breakpoint, 'should have set a breakpoint');
+          var breakpoint = body.breakpoint;
+          assert.ok(breakpoint.id, 'breakpoint should have an id');
+          assert.ok(breakpoint.location, 'breakpoint should have a location');
+          assert.strictEqual(breakpoint.location.path, 'test.js');
+          return { debuggee: debuggee, breakpoint: breakpoint };
+        });
+        return result;
+      })
+      .then(function(result) {
+        assert.ok(result.breakpoint);
+        assert.ok(result.debuggee);
+        console.log('-- waiting a bit before running fib');
+        return Q.delay(10 * 1000).then(function() { return result; });
+      })
+      .then(function(result) {
+        console.log('-- waiting before checking if the log was written');
+        return Q.delay(10 * 1000).then(function() { return result; });
+      })
+      .then(function(result) {
+        assert(transcript.indexOf('n is: 10') !== -1);
+        deleteBreakpoint(result.debuggee, result.breakpoint).then();
+        return result.debuggee;
+      })
       .then(function(debuggee) {
         // Set a breakpoint
         console.log('-- setting a breakpoint');
@@ -183,6 +223,8 @@ function runTest() {
         });
         assert.ok(arg, 'should find the n argument');
         assert.strictEqual(arg.value, '10');
+        console.log('-- checking log point was hit again');
+        assert.ok(transcript.split('n is: 10').length > 4);
         console.log('Test passed');
         process.exit(0);
       })
@@ -198,6 +240,7 @@ function runTest() {
 }
 
 if (cluster.isMaster) {
+  cluster.setupMaster({ silent: true });
   var handler = function(m) {
     assert.ok(m.private_, 'debuglet has initialized');
     var debuglet = m.private_;
@@ -212,8 +255,13 @@ if (cluster.isMaster) {
       agent = m;
     }
   };
+  var stdoutHandler = function(chunk) {
+    transcript += chunk;
+  };
   for (var i = 0; i < 3; i++) {
-    cluster.fork().on('message', handler);
+    var worker = cluster.fork();
+    worker.on('message', handler);
+    worker.process.stdout.on('data', stdoutHandler);
   }
   runTest();
 } else {

test/standalone/test-debuglet.js

@@ -35,9 +35,9 @@ var bp = {
   action: 'CAPTURE',
   location: { path: 'fixtures/foo.js', line: 2 }
 };
-var logBp = {
+var errorBp = {
   id: 'testLog',
-  action: 'LOG',
+  action: 'FOO',
   location: { path: 'fixtures/foo.js', line: 2 }
 };
 
@@ -166,12 +166,12 @@ describe(__filename, function(){
       })
       .get(BPS_PATH + '?success_on_timeout=true')
       .reply(200, {
-        breakpoints: [bp, logBp]
+        breakpoints: [bp, errorBp]
       })
-      .put(BPS_PATH + '/' + logBp.id, function(body) {
+      .put(BPS_PATH + '/' + errorBp.id, function(body) {
         var status = body.breakpoint.status;
         return status.isError &&
-          status.description.format.indexOf('action is CAPTURE') !== -1;
+          status.description.format.indexOf('actions are CAPTURE') !== -1;
       })
       .reply(200);
 
@@ -280,5 +280,22 @@ describe(__filename, function(){
       assert.deepEqual(Debuglet.mapSubtract({}, b), []);
     });
   });
+
+  describe('format', function() {
+    it('should be correct', function() {
+      assert.deepEqual(Debuglet.format('hi', [5]), 'hi');
+      assert.deepEqual(Debuglet.format('hi $0', [5]), 'hi 5');
+      assert.deepEqual(Debuglet.format('hi $0 $1', [5, 'there']), 'hi 5 there');
+      assert.deepEqual(Debuglet.format('hi $0 $1', [5]), 'hi 5 $1');
+      assert.deepEqual(Debuglet.format('hi $0 $1 $0', [5]), 'hi 5 $1 5');
+      assert.deepEqual(Debuglet.format('hi $$', [5]), 'hi $');
+      assert.deepEqual(Debuglet.format('hi $$0', [5]), 'hi $0');
+      assert.deepEqual(Debuglet.format('hi $00', [5]), 'hi 50');
+      assert.deepEqual(Debuglet.format('hi $0', ['$1', 5]), 'hi $1');
+      assert.deepEqual(Debuglet.format('hi $11',
+        [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 'a', 'b', 'c', 'd']
+      ), 'hi b');
+    });
+  });
 });