timers: fix processing of nested same delay timers

lib/timers.js

@@ -160,7 +160,7 @@ function listOnTimeout() {
   debug('timeout callback %d', msecs);
 
   var now = TimerWrap.now();
-  debug('now: %s', now);
+  debug('now: %d', now);
 
   var diff, timer;
   while (timer = L.peek(list)) {
@@ -169,7 +169,11 @@ function listOnTimeout() {
     // Check if this loop iteration is too early for the next timer.
     // This happens if there are more timers scheduled for later in the list.
     if (diff < msecs) {
-      this.start(msecs - diff, 0);
+      var timeRemaining = msecs - (TimerWrap.now() - timer._idleStart);
+      if (timeRemaining < 0) {
+        timeRemaining = 0;
+      }
+      this.start(timeRemaining, 0);
       debug('%d list wait because diff is %d', msecs, diff);
       return;
     }

test/common.js

@@ -7,6 +7,7 @@ var os = require('os');
 var child_process = require('child_process');
 const stream = require('stream');
 const util = require('util');
+const Timer = process.binding('timer_wrap').Timer;
 
 const testRoot = path.resolve(process.env.NODE_TEST_DIR ||
                               path.dirname(__filename));
@@ -484,3 +485,9 @@ exports.nodeProcessAborted = function nodeProcessAborted(exitCode, signal) {
     return expectedExitCodes.indexOf(exitCode) > -1;
   }
 };
+
+exports.busyLoop = function busyLoop(time) {
+  var startTime = Timer.now();
+  var stopTime = startTime + time;
+  while (Timer.now() < stopTime) {}
+};

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

@@ -0,0 +1,81 @@
+'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 Timer = process.binding('timer_wrap').Timer;
+
+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 = Timer.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/nodejs/node-v0.x-archive/issues/15447 and
+    // https://github.com/nodejs/node-v0.x-archive/issues/9333..
+    assert(latestDelay < TIMEOUT * 1.5);
+    if (callback)
+      return callback();
+  } else {
+    // block by busy-looping to trigger the issue
+    common.busyLoop(TIMEOUT);
+
+    timeCallbackScheduled = Timer.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);

test/parallel/test-timers-nested.js

@@ -0,0 +1,39 @@
+'use strict';
+
+const assert = require('assert');
+const common = require('../common');
+
+// Make sure we test 0ms timers, since they would had always wanted to run on
+// the current tick, and greater than 0ms timers, for scenarios where the
+// outer timer takes longer to complete than the delay of the nested timer.
+// Since the process of recreating this is identical regardless of the timer
+// delay, these scenarios are in one test.
+const scenarios = [0, 100];
+
+scenarios.forEach(function(delay) {
+  var nestedCalled = false;
+
+  setTimeout(function A() {
+    // Create the nested timer with the same delay as the outer timer so that it
+    // gets added to the current list of timers being processed by
+    // listOnTimeout.
+    setTimeout(function B() {
+      nestedCalled = true;
+    }, delay);
+
+    // Busy loop for the same timeout used for the nested timer to ensure that
+    // we are in fact expiring the nested timer.
+    common.busyLoop(delay);
+
+    // The purpose of running this assert in nextTick is to make sure it runs
+    // after A but before the next iteration of the libuv event loop.
+    process.nextTick(function() {
+      assert.ok(!nestedCalled);
+    });
+
+    // Ensure that the nested callback is indeed called prior to process exit.
+    process.on('exit', function onExit() {
+      assert.ok(nestedCalled);
+    });
+  }, delay);
+});