timers: fix processing of nested timers

Whenever a timer is scheduled within another timer, there are a few known issues that we are fixing: * Whenever the timer being scheduled has the same timeout value as the outer timer, the newly created timer can fire on the same tick of the event loop instead of during the next tick of the event loop * Whenever a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect This commit consists of nodejs/node-v0.x-archive#17203 and nodejs/node-v0.x-archive#25763. Fixes: nodejs/node-v0.x-archive#9333 Fixes: nodejs/node-v0.x-archive#15447 Fixes: nodejs/node-v0.x-archive#25607 Fixes: #5426 PR-URL: #3063
nodejs · bnoordhuis · Jan 12, 2016 · Jul 10, 2016 · Jul 8, 2016 · Jul 6, 2016
commit 9d9bd3cabbab1a2327843e65e0377affadb4dd43
diff --git a/lib/timers.js b/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;
     }

diff --git a/test/common.js b/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) {}
+};
diff --git a/test/parallel/test-timers-blocking-callback.js b/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);
diff --git a/test/parallel/test-timers-nested.js b/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);
+});