clearTimeout with invalid handle cause program runs longer

[tdzl2003]

• Version: Tested on 6.0.0
• Platform: Tested on Windows & MacOS
• Subsystem: Timer

This program cost 20 seconds, but 10.5 seconds was expected:

var handle = setTimeout(function(){
    clearTimeout(handle);
    handle = setTimeout( function() {
    }, 10000 );
    setTimeout( function() {
        clearTimeout( handle );
    }, 500 );
}, 10000);

But all below codes work as expected:

var handle = setTimeout(function(){
    clearTimeout(handle);
    handle = setTimeout( function() {
    }, 10000 );
    setTimeout( function() {
        clearTimeout( handle );
    }, 500 );
}, 2000);  // <-- different delay 

var handle = setTimeout(function(){
        //clearTimeout(handle);  <-- comment this line.
    handle = setTimeout( function() {
    }, 10000 );
    setTimeout( function() {
        clearTimeout( handle );
    }, 500 );
}, 10000);

Does clearTimeout with a invalid handle causes this problem?

[Fishrock123]

The following code works:

var handle = setTimeout(function() {

  clearTimeout(handle)

  var _handle = setTimeout(function() {}, 10001)

  setTimeout(function() {
    clearTimeout(_handle);
  }, 500)

}, 10000)

This is a more elaborate form of #5426 which will be fixed by #3063

[misterdjules]

This is not a duplicate of #5426. Applying the fix in #3063 on top of current node's master still allows to reproduce the problem described in this issue.

The problem that this issue describes is that, in the following code:

var handle = setTimeout(function(){
    clearTimeout(handle);
    handle = setTimeout( function() {
    }, 10000 );
    setTimeout( function() {
        clearTimeout( handle );
    }, 500 );
}, 10000);

when the callback of the first timer with a 10000 delay fires, this is (some of) what happens:

1. a reference to the timers list that represents all timers with a 10000ms delay is grabbed. This list contains one "userland timer".
2. that list is cleared by clearTimeout(handle). The list of timers with a 10000ms delay is removed from the list of lists of timers because at that time there was only 1 timer in that list.
3. A new timer instance with a 10000ms delay is added, so a new list of timers is created. Note that the "reference to the timers list that represents all timers with a 10000ms delay" grabbed at point 1 still references the old empty list.
4. The callback of the first 10000ms delay timer completes and listOnTimeout determines that the list of timers referenced by list, the "old timers list" for timers with a 10000 delay, is empty. But instead of removing that old list from the list of lists of timers, it removes the new list that contains the newly scheduled 10000ms delayed timer.
5. When the callback of the 500ms delayed timer fires, it clears the most recent 10000ms timer instance, which fails to find any list of timers with 10000ms delay and thus doesn't close the handle of that new timer, which keeps the libuv event loop open until the kOnTimeout callback is called.

Here's a quick fix that I put together to demonstrate the problem. This is not a definite fix, it's mentioned here just to illustrate the problem. It is likely that a better fix can be written:

diff --git a/lib/timers.js b/lib/timers.js
index 7379cfe..b7f2259 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -212,9 +212,11 @@ function listOnTimeout() {
   assert(L.isEmpty(list));
   this.close();
   if (list._unrefed === true) {
-    delete unrefedLists[msecs];
+    if (list === unrefedLists[msecs])
+      delete unrefedLists[msecs];
   } else {
-    delete refedLists[msecs];
+    if (list === refedLists[msecs])
+      delete refedLists[msecs];
   }
 }

With that fix, the problem cannot be reproduced and all tests pass. I'll try to dig a bit deeper in the next few days to come up with a better fix and tests, but if anyone is willing to take a shot at it, I'd be glad to help them too.

From what I described above, it seems this issue should be kept open, thus I'm reopening it.

[Fishrock123]

Oh nice catch, I think I see what you are saying. Yes, that would be a bug in my refactoring.

The patch could probably be simplified a bit also.

[Fishrock123]

@misterdjules we don't really label the effected versions quite like that these days though...

Also this exact bug cannot exist of 0.x since my code is not there.

[misterdjules]

The patch could probably be simplified a bit also.

That's quite possible, the current diff was added just to illustrate the problem, I'll clarify that in my comment.

Also this exact bug cannot exist of 0.x since my code is not there.

This bug also affects some v0.x versions, at least latest v0.10.x and v0.12.x versions. I had tested it was the case. If you run the code mentioned by the reporter of this issue with node v0.10.x and v0.12.x, I believe you'll reach the same conclusions.

That bug wasn't caused by the refactoring in #4007. For instance, in v0.10.x versions it is caused by the same problem described in my comment above, the fact that a list of timers created in a nested timer's callback can be incorrectly destroyed by the outer timer's callback.

@misterdjules we don't really label the effected versions quite like that these days though...

I find it very useful to document which versions are affected by a given bug. In this case, anyone coming back to this later would be able to determine which versions are affected without reading through all the comments and without having to run tests themselves.

Is it that we're using different labels for that now? If so, then let's set the new labels, otherwise I don't understand how adding valuable metadata would hurt.

[Fishrock123]

ergh, yes I see how it it also exists in 0.x, the fix is similar.

[misterdjules]

@Fishrock123 The problem also affects the master branch, shouldn't we keep the master label set, or is it meant to be used for other purposes?

[misterdjules]

The fix in 7d75338 should be able to make its way to v6.x and v4.x releases soon. It's unlikely it will make it to any v0.12 and v0.10 release unless there's enough evidence that a significant number of users are impacted by it on these release lines.