diff --git a/lib/timers.js b/lib/timers.js index 9dbae32405cf6e..7379cfe3591e02 100644 --- 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 index f9d80ff1490e42..308411a13d3427 100644 --- 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 new file mode 100644 index 00000000000000..114c435a6af726 --- /dev/null +++ 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 new file mode 100644 index 00000000000000..17b397d33cd860 --- /dev/null +++ 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); +});