nested setTimeout calls can lead to premature process exit

[csosborn]

Certain combinations of nested setTimeout and clearTimeout calls lead to a the node process exiting improperly. The exit is clean, with the process object emitting an "exit" event and status code of 0, but it nevertheless happens too early. Additional background is at https://groups.google.com/forum/#!topic/nodejs/w1wBjg61rQg.

Please see https://gist.github.com/1590128 for code that will reproduce this behavior.

[bnoordhuis]

Confirmed. Tentative fix in bnoordhuis/libuv@1c527d2.

[dfellis]

This is not a Node problem.

Change the timeouts to 20 and 50 instead of 2 and 5 and you'll see it work.

The issue is that the setTimeout function only guarantees down to 4ms intervals.

The events are happening out of the specified order and is therefore producing undefined behavior. I'd have to dig through the guts of the V8 engine to see what's happening within the queue, but my guess is that the clearInterval, since it is happening within an event itself, clears a necessary interval to continue this godforsaken loop.

[dfellis]

To be a bit more helpful, for whatever it is you're trying to do, you probably want to use process.nextTick, instead.

[bnoordhuis]

This is not a Node problem.

No, but it is a libev/libuv issue. One symptom is that the event loop's reference count sometimes drops below zero.

[dfellis]

Then this may well have exposed a bug in the library. I don't think it changes the fact that the example code could be executed out of expected order, however.

It's a problem with any setTimeout; if the callback is calculating the first 5 million digits of pi the second callback isn't going to fire until the first has finished, anyways.

[csosborn]

I chose those particular timeout values to maximize the chance of the bug occurring quickly and repeatably, purely for the sake of easy debugging. When I first encountered this problem, it was with timeouts closer to 10ms and 5000ms, respectively. It happens then too, but infrequently enough that it's harder to demonstrate.

The exact timing isn't important, but if the events are happening out the specified order, then I think that's a Node bug. While I'm perfectly happy to see God forsake this loop, Node should not. I'm using it for a good purpose: I need to time out unit tests that fail to exit cleanly, but I don't want to do so using a single setTimeout because then it becomes much harder to debug the code under test. A single timeout is likely to expire and kill the test while I'm still stepping through in the debugger, whereas a five-second fuse constructed of 500 consecutive 10ms setTimeouts does not exhibit that problem. When the event loop pauses, so does the fuse.

[cowboy]

I'm experiencing what I believe to be the exact same issue. At no point should this code exit, since the interval is never cleared, but it does. The setTimeout and clearTimeout should in no way impact the setInterval, but they somehow do.

Note that while I initially had both delays set to much lower values than 100, using node v0.6.7 on OS X 10.7, this much higher delay value doesn't prevent the process from exiting early. I typically see the console.log between 3-5 times before it exits.

var i = 0;
var id;
// Create a never-ending interval. This should guarantee that the node process
// never exits, since it's never cleared.
setInterval(function() {
  console.log(++i);
  // Clear timeout if one exists.
  if (id) { clearTimeout(id); }
  // Create a timeout.
  id = setTimeout(function() {}, 100);
}, 100);

output:

[cowboy@CowBook:~]
[07:07:11] $ node test.js 
1
2
3
4

[cowboy@CowBook:~]
[07:07:11] $ 

[cowboy]

FWIW, I don't know if this has any bearing on the issue, but in Chromium 117892 console, the interval goes forever.

[maritz]

Works in v0.4.12 but seems broken since v0.6.0

[bjornstar]

I just ran into the same problem, it only happens on linux for me.

I created a setInterval / setTimeout benchmark (https://gist.github.com/1668261) and it won't complete on either of my two linux boxes, but completes fine on three of my windows boxes.

Is there an ETA to this fix going in? v0.6.8 was released 5 days ago and did not include this fix. I also tried running 0.7.2-pre and it still fails.

[bnoordhuis]

@bjornstar: bnoordhuis/libuv@1c527d2 seems to have fixed the issue but I haven't been able to come up with a good regression test yet.

[bjornstar]

@bnoordhuis: I created a test for this and submitted a pull request (#2644)

[bjornstar]

Any progress on this issue? Is there a problem with the pull request?

[deitch]

Yep, this one tripped me up to with jsdom and zombie. I just use TJ's "n" to now run that code under

n use 0.4.10 ./app.js

but that is kind of backwards. Looking forward to the fix here.

[piscisaureus]

Doesn't happen in windows, so @bnoordhuis's theory that it is an libuv-unix issue seems likely.

[bjornstar]

Still broken on v0.6.11, when is this fix going in? clearTimeout is unsafe on linux because it will destroy all your timers, even those created by setInterval.

[bnoordhuis]

The fix landed in master in af7960b. I'm debating the wisdom of back-porting it to v0.6.x. Can you guys test master and report your findings?

[csosborn]

I just built from master (node reports 0.7.5-pre) and the behavior doesn't appear to have changed. Both my original reproducer and cowboy's much simpler code still exit too soon, just as in the v0.6 series. Both work fine in the v0.4 series.

[bnoordhuis]

I just built from master (node reports 0.7.5-pre)

That's not the current master, you're a release behind. FWIW, the test cases are passing for me with bab59f3.

[csosborn]

You're right, I must have failed to to pull newer commits before checking out master. I tried again with 0.7.6-pre and all appears to be well; both test programs work properly. Thank you!

My sense is that this is worth backporting, but I have no clear idea of the risks. I can work around the problem until the stable v0.8 release arrives, but I'm not sure about other people.

[bnoordhuis]

The fix has been back-ported in 3aa2fd3, it'll be part of the next v0.6 release.

[deitch]

Hats off!

[bjornstar]

Thanks @bnoordhuis I'll check back on this when I return from my trip.

[bjornstar]

Confirming that this is fixed in v0.6.12, thanks Ben!

[deitch]

Yep, just used TJ's n to install 0.6.12, and ran tests in 0.6.10 (issue) and 0.6.12 (no problems).

Thanks, Ben!