Port from joyent/node: timers: fix timeout when added in timer's callback

lib/timers.js

@@ -57,10 +57,19 @@ function listOnTimeout() {
   debug('timeout callback %d', msecs);
 
   var now = Timer.now();
-  debug('now: %s', now);
+  debug('now: %d', now);
 
   var diff, first, threw;
   while (first = L.peek(list)) {
+    // If the previous iteration caused a timer to be added,
+    // update the value of "now" so that timing computations are
+    // done correctly. See test/parallel/test-timers-blocking-callback.js
+    // for more information.
+    if (now < first._idleStart) {
+      now = Timer.now();
+      debug('now: %d', now);
+    }
+
     diff = now - first._idleStart;
     if (diff < msecs) {
       list.start(msecs - diff, 0);

test/common.js

@@ -453,3 +453,9 @@ exports.fileExists = function(pathname) {
     return false;
   }
 };
+
+exports.busyLoop = function busyLoop(time) {
+  var startTime = Date.now();
+  var stopTime =  startTime + time;
+  while (Date.now() < stopTime);
+};

test/parallel/test-timers-blocking-callback.js

@@ -0,0 +1,80 @@
+'use strict';
+
+/*
+ * This is a regression test for https://github.com/joyent/node/issues/15447
+ * and https://github.com/joyent/node/issues/9333.
+ *
+ * When a timer is added in another timer's callback, its underlying timer
+ * handle was started with a timeout that was actually incorrect.
+ *
+ * The reason was that the value that represents the current time was not
+ * updated between the time the original callback was called and the time
+ * the added timer was processed by timers.listOnTimeout. That lead the
+ * logic in timers.listOnTimeout to do an incorrect computation that made
+ * the added timer fire with a timeout of scheduledTimeout +
+ * timeSpentInCallback.
+ *
+ * This test makes sure that a timer added by another timer's callback
+ * fire with the expected timeout.
+ *
+ * It makes sure that it works when the timers list for a given timeout is
+ * empty (see testAddingTimerToEmptyTimersList) and when the timers list
+ * is not empty (see testAddingTimerToNonEmptyTimersList).
+ */
+
+const assert = require('assert');
+const common = require('../common');
+
+const TIMEOUT = 100;
+
+var nbBlockingCallbackCalls = 0;
+var latestDelay = 0;
+var timeCallbackScheduled = 0;
+
+function initTest() {
+  nbBlockingCallbackCalls = 0;
+  latestDelay = 0;
+  timeCallbackScheduled = 0;
+}
+
+function blockingCallback(callback) {
+  ++nbBlockingCallbackCalls;
+
+  if (nbBlockingCallbackCalls > 1) {
+    latestDelay = Date.now() - timeCallbackScheduled;
+    // Even if timers can fire later than when they've been scheduled
+    // to fire, they should more than 50% later with a timeout of
+    // 100ms. Firing later than that would mean that we hit the regression
+    // highlighted in
+    // https://github.com/joyent/node/issues/15447 and
+    // https://github.com/joyent/node/issues/9333.
+    assert(latestDelay < TIMEOUT * 1.5);
+    if (callback)
+      return callback();
+  } else {
+    // block by busy-looping to trigger the issue
+    common.busyLoop(TIMEOUT);
+
+    timeCallbackScheduled = Date.now();
+    setTimeout(blockingCallback, TIMEOUT);
+  }
+}
+
+function testAddingTimerToEmptyTimersList(callback) {
+  initTest();
+  // Call setTimeout just once to make sure the timers list is
+  // empty when blockingCallback is called.
+  setTimeout(blockingCallback.bind(null, callback), TIMEOUT);
+}
+
+function testAddingTimerToNonEmptyTimersList() {
+  initTest();
+  // Call setTimeout twice with the same timeout to make
+  // sure the timers list is not empty when blockingCallback is called.
+  setTimeout(blockingCallback, TIMEOUT);
+  setTimeout(blockingCallback, TIMEOUT);
+}
+
+// Run the test for the empty timers list case, and then for the non-empty
+// timers list one
+testAddingTimerToEmptyTimersList(testAddingTimerToNonEmptyTimersList);