Resume logging after log quota is hit

Matt Loring · Matt Loring · commit 1e083488f678 · 2016-06-10T17:03:29.000-07:00
diff --git a/lib/debuglet.js b/lib/debuglet.js
@@ -334,7 +334,10 @@ Debuglet.prototype.addBreakpoint_ = function(breakpoint, cb) {
     that.activeBreakpointMap_[breakpoint.id] = breakpoint;
 
     if (breakpoint.action === 'LOG') {
-      that.v8debug_.log(breakpoint, Debuglet.format,
+      that.v8debug_.log(breakpoint,
+        function(fmt, exprs) {
+          console.log('LOGPOINT:', Debuglet.format(fmt, exprs));
+        },
         function() {
           return that.completedBreakpointMap_[breakpoint.id];
         });
diff --git a/lib/v8debugapi.js b/lib/v8debugapi.js
@@ -206,12 +206,33 @@ module.exports.create = function(logger_, config_, fileStats_) {
      * @param {Breakpoint} breakpoint
      * @param {Function} callback
      */
-    log: function(breakpoint, format, shouldStop) {
+    log: function(breakpoint, print, shouldStop) {
       var num = breakpoints[breakpoint.id].v8Breakpoint.number();
+      var logsThisSecond = 0;
+      var timesliceEnd = Date.now() + 1000;
       var listener = onBreakpointHit.bind(
-          null, breakpoint,
-          createLogpointHandler(breakpoint, format, shouldStop, listener));
-
+          null, breakpoint, function(err) {
+        var currTime = Date.now();
+        if (currTime > timesliceEnd) {
+          logsThisSecond = 0;
+          timesliceEnd = currTime + 1000;
+        }
+        print(breakpoint.logMessageFormat,
+          breakpoint.evaluatedExpressions.map(JSON.stringify));
+        logsThisSecond++;
+        if (shouldStop()) {
+          listeners[num].enabled = false;
+        } else {
+          if (logsThisSecond >= config.log.maxLogsPerSecond) {
+            listeners[num].enabled = false;
+            setTimeout(function() {
+              if (!shouldStop()) {
+                listeners[num].enabled = true;
+              }
+            }, config.log.logDelaySeconds * 1000);
+          }
+        }
+      });
       listeners[num] = { enabled: true, listener: listener };
     },
 
@@ -327,33 +348,6 @@ module.exports.create = function(logger_, config_, fileStats_) {
     setImmediate(function() { cb(null); }); // success.
   }
 
-  function createLogpointHandler(breakpoint, format, shouldStop, listener) {
-    var logsThisSecond = 0;
-    var timesliceEnd = Date.now() + 1000;
-    var num = breakpoints[breakpoint.id].v8Breakpoint.number();
-    return function(err) {
-      var currTime = Date.now();
-      if (currTime > timesliceEnd) {
-        logsThisSecond = 0;
-        timesliceEnd = currTime + 1000;
-      }
-      var message = format(breakpoint.logMessageFormat,
-        breakpoint.evaluatedExpressions.map(JSON.stringify));
-      logsThisSecond++;
-      console.log('LOGPOINT:', message);
-      if (shouldStop()) {
-        listeners[num].enabled = false;
-      } else {
-        if (logsThisSecond > config.log.maxLogsPerSecond) {
-          listeners[num].enabled = false;
-          setTimeout(function() {
-            listeners[num].enabled = true;
-          }, config.log.logDelaySeconds * 1000);
-        }
-      }
-    };
-  }
-
   function endsWith(str, suffix) {
     if (typeof String.prototype.endsWith === 'function') {
       return str.endsWith(suffix);
diff --git a/test/e2e/test-log-throttling.js b/test/e2e/test-log-throttling.js
@@ -201,7 +201,7 @@ if (cluster.isMaster) {
   runTest();
 } else {
   var agent = require('../..');
-  agent.private_.config_.log.maxLogsPerSecond = 1;
+  agent.private_.config_.log.maxLogsPerSecond = 2;
   agent.private_.config_.log.logDelaySeconds = 5;
   setTimeout(process.send.bind(process, agent), 7000);
   setInterval(fib.bind(null, 12), 500);
diff --git a/test/test-v8debugapi.js b/test/test-v8debugapi.js
@@ -386,6 +386,53 @@ describe('v8debugapi', function() {
     });
   });
 
+  describe('log', function() {
+    var oldLPS;
+    var oldDS;
+
+    before(function() {
+      oldLPS = config.log.maxLogsPerSecond;
+      oldDS = config.log.logDelaySeconds;
+      config.log.maxLogsPerSecond = 1;
+      config.log.logDelaySeconds = 1;
+    });
+
+    after(function() {
+      config.log.maxLogsPerSecond = oldLPS;
+      config.log.logDelaySeconds = oldDS;
+      assert(stateIsClean(api));
+    });
+
+    it('should throttle correctly', function(done) {
+      var completed = false;
+      var bp = {
+        id: breakpointInFoo.id,
+        location: breakpointInFoo.location,
+        action: 'LOG',
+        logMessageFormat: 'cat'
+      };
+      api.set(bp, function(err) {
+        var transcript = '';
+        var runCount = 0;
+        assert.ifError(err);
+        api.log(bp, function(fmt) { transcript += fmt; },
+          function() { return completed; });
+        var interval = setInterval(function() {
+          foo(1);
+          runCount++;
+        }, 100);
+        setTimeout(function() {
+          completed = true;
+          assert.equal(transcript, 'catcat');
+          assert(runCount > 12);
+          clearInterval(interval);
+          api.clear(bp);
+          done();
+        }, 1500);
+      });
+    });
+  });
+
   describe('set and wait', function() {
 
     it('should be possible to wait on a breakpoint', function(done) {
@@ -431,7 +478,7 @@ describe('v8debugapi', function() {
       var bp = {
         id: breakpointInFoo.id,
         action: 'LOG',
-        log_message_format: 'Hello World',
+        logMessageFormat: 'Hello World',
         location: breakpointInFoo.location
       };
       api.set(bp, function(err) {
