timers: fix not to close reused timer handle #11646

shigeki · 2017-03-02T04:06:52Z

This issue was originally reported by @darai0512 via private communication.

He found that timer.unref in setInterval callback leads the timer not to be repeated.
It can reproduced with this sample that setInterval counter1 stops at 0.

const net = require('net');
let counter1 = 0;
const server = net.createServer().listen(0);

const timer1 = setInterval(() => {
  console.log('counter1:', counter1);
  timer1.unref();
  if (counter1++ === 10)
    server.close();
}, 1);

The timer handle is reused when it is unrefed in order to avoid new
callback in beforeExit(#3407). If it is unrefed within a setInterval
callback, the reused timer handle is closed so that setInterval no
longer keep working. This fix does not close the handle in case of
setInterval.

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
commit message follows commit guidelines

Affected core subsystem(s)

timer

CC: @Fishrock123, @misterdjules for timer maintainer.

shigeki · 2017-03-02T04:08:03Z

CI is running on https://ci.nodejs.org/job/node-test-pull-request/6650/.

Fishrock123 · 2017-03-02T20:30:27Z

I feel like this might expose some list bug where you might be able to schedule a timer onto the wrong, or a dead, list. That would have also occurred before if it didn't break entirely.

Looking into it more, need a bit of time to think about this.

misterdjules · 2017-03-02T21:23:36Z

lib/timers.js

@@ -232,6 +231,12 @@ function listOnTimeout() {
 } else if (list === refedLists[msecs]) {
 delete refedLists[msecs];
 }
+
+ // do not close reused handler which is unrefed in setInterval
+ if (this.owner && this.owner._repeat)


Is the test on this.owner._repeat needed? That is, isn't the test on this.owner sufficient?

At first, I worried the case of using setTimeout but I found that it doesn't matter.
Right, this.owner._repeat is not necessary. Fixed.

misterdjules · 2017-03-02T21:25:10Z

lib/timers.js

@@ -232,6 +231,12 @@ function listOnTimeout() {
 } else if (list === refedLists[msecs]) {
 delete refedLists[msecs];
 }
+
+ // do not close reused handler which is unrefed in setInterval


This comment seems a bit too specific, even if it is correct. What about:

// Do not close the underlying handle if its ownership has changed (e.g it was unrefed in its callback).

?

misterdjules · 2017-03-02T21:28:18Z

test/parallel/test-timers-unrefed-in-callback.js

@@ -0,0 +1,49 @@
+'use strict';
+// Check that unrefed setInterval timer keeps running even if it is


Nit: I would rephrase this as:

// Checks that setInterval timers keep running even when they're unrefed within their callback.

misterdjules · 2017-03-02T21:41:28Z

test/parallel/test-timers-unrefed-in-callback.js

+}
+
+process.on('exit', () => {
+ assert.strictEqual(counter2, 11);


I'm not sure asserting on a specific number of occurrences that the setInterval was called is robust. For instance, it seems that if clearInterval didn't work properly after merging this change but it took less than 1ms to complete one turn of the event loop and thus close the server handle, this test wouldn't fail.

counter2 increments up to 11 before server.close() so that the test is not failed even when server is closed immediately. The test can be finished without need to wait for the next event loop.

Here's what I understand of how the test Test2 works and what its goal is:

The goal is to make sure that, when calling clearInterval on an unrefed() repeating timer created with setInterval, the timer doesn't fire anymore.

To test that, we:

create a repeating timer with setInterval

make sure it fires 11 times

clear it

test that it was properly cleared by testing that, when the process exits, the value of counter2 is 11.

What I'm saying is that, even if the timer was not cleared properly, it would be possible for this test to:

not fire the cleared interval's callback (and thus leave the value of counter2 at 11)

close the server handle

let the process exit

if it took less than the time it takes for the interval timer to fire (1ms or more) to close the server and terminate the event loop. In that case, we'd still think the test succeeded, when clearly the implementation would have a bug.

Does that make sense or am I missing something?

@misterdjules I've got it. That can be resolve by swapping Test1 and Test2 for it needs 10 msec after testing clearInterval. Fixed in 589d661cdd8d83e848cea5b09d4dd2cdae2fe365. PTAL.

misterdjules

So far it seems to me like it's moving in a good direction. There are still some questions left and I would like to get more details on @Fishrock123's concerns before approving this though.

misterdjules · 2017-03-02T21:50:19Z

@Fishrock123

I feel like this might expose some list bug where you might be able to schedule a timer onto the wrong, or a dead, list. That would have also occurred before if it didn't break entirely.

Would you mind elaborating on that, maybe with some sample code?

Fishrock123

Ok I think unref() and reuse() already cover my concern.

left a comment, will review the test after

Fishrock123 · 2017-03-02T23:44:24Z

lib/timers.js

@@ -232,6 +231,12 @@ function listOnTimeout() {
 } else if (list === refedLists[msecs]) {
 delete refedLists[msecs];


Would it still work if this.close() was placed into both of these ifcases? I think that may be a better and more robust patch.

It would work as far as I checked. I also made an additional test that has require('timers')._unrefActive(timer1) and found that the timer handle is not reused in that case. So it is okay.
Honestly, I'm not sure whether the following two conditions are equivalent or not. I think the latter is clearly understandable.

if (list._unrefed === true && list === unrefedLists[msecs]) { delete unrefedLists[msecs]; this.close(); } else if (list === refedLists[msecs]) { delete refedLists[msecs]; this.close(); }

// Do not close the underlying handle if its ownership has changed // (e.g it was unrefed in its callback). if (this.owner) return; this.close();

My thinking is that you only actually want to close the handle if the list was in a pool.

There are more obscure parts of the timers code imo so I don't think it is an issue.

@Fishrock123

My thinking is that you only actually want to close the handle if the list was in a pool.

Do you mean that we want to close the TimerWrap handle only if the list is still in a pool?

Does that diff reflects the change you had in mind:

diff --git a/lib/timers.js b/lib/timers.js index 0784f7f..fb81467 100644 --- a/lib/timers.js +++ b/lib/timers.js @@ -160,6 +160,7 @@ function TimersList(msecs, unrefed) { } function listOnTimeout() { + var pool; var list = this._list; var msecs = list.msecs; @@ -222,15 +223,27 @@ function listOnTimeout() { // As such, we can remove the list and clean up the TimerWrap C++ handle. debug('%d list empty', msecs); assert(L.isEmpty(list)); - this.close(); - - // Either refedLists[msecs] or unrefedLists[msecs] may have been removed and - // recreated since the reference to `list` was created. Make sure they're - // the same instance of the list before destroying. - if (list._unrefed === true && list === unrefedLists[msecs]) { - delete unrefedLists[msecs]; - } else if (list === refedLists[msecs]) { - delete refedLists[msecs]; + + if (list._unrefed) { + pool = unrefedLists; + } else { + pool = refedLists; + } + + /* + * If the timers list that was just traversed and is empty actually doesn't + * exist anymore (e.g because it was reused to create an unrefed timer), don't + * close the underlying timerwrap, its ownership changed. + */ + if (pool[msecs] !== undefined) { + this.close(); + } + + // The timers list may have been removed and recreated since the reference to + // `list` was created. Make sure they're the same instance of the list before + // destroying. + if (list === pool[msecs]) { + delete pool[msecs]; } }

?

I would think that the owner property represents ownership for a specific timer handle better than the belonging of its timer list to a given timer lists pool, so I have a preference for:

// Do not close the underlying handle if its ownership has changed // (e.g it was unrefed in its callback). if (this.owner) return; this.close();

I think that if we check the closing condition weather the list was in a pool or not.

+ if (pool[msecs] !== undefined) { + this.close(); + }

is better.
Otherwise, I prefer to check owner property.

I'm very confused as to why what I originally suggested doesn't do the job just fine?

if (list._unrefed === true && list === unrefedLists[msecs]) { delete unrefedLists[msecs]; this.close(); } else if (list === refedLists[msecs]) { delete refedLists[msecs]; this.close(); }

Keep in mind that reuse() is called before this if unrefing is actually re-using the handle and it already removed the list from the pool:

node/lib/timers.js

Lines 274 to 293 in 75cdc89

// A convenience function for re-using TimerWrap handles more easily.

//

// This mostly exists to fix https://github.com/nodejs/node/issues/1264.

// Handles in libuv take at least one `uv_run` to be registered as unreferenced.

// Re-using an existing handle allows us to skip that, so that a second `uv_run`

// will return no active handles, even when running `setTimeout(fn).unref()`.

function reuse(item) {

L.remove(item);

var list = refedLists[item._idleTimeout];

// if empty - reuse the watcher

if (list && L.isEmpty(list)) {

debug('reuse hit');

list._timer.stop();

delete refedLists[item._idleTimeout];

return list._timer;

}

return null;

}

Essentially I don't see why we'd bother to check .owner() if doing it in those conditionals is deterministic anyways?

@Fishrock123

Essentially I don't see why we'd bother to check .owner() if doing it in those conditionals is deterministic anyways?

For the reason I mentioned above:

I would think that the owner property represents ownership for a specific timer handle better than the belonging of its timer list to a given timer lists pool

In other words, it seems it would be more robust to check the owner property than rely on what seems to be an implementation detail.

The solution you're suggesting also duplicates code, and doesn't include any documentation about why the underlying TimerWrap handle should be closed in some cases, and not in others.

What you're suggesting would indeed fix the problem, but it seems to me it would lead to a less robust solution that would be more difficult to understand.

What you're suggesting would indeed fix the problem, but it seems to me it would lead to a less robust solution that would be more difficult to understand.

I agree this.
And it is the point that we don't have an agreement with @Fishrock123 from his comment of

There are more obscure parts of the timers code imo so I don't think it is an issue.

misterdjules · 2017-03-06T18:30:13Z

test/parallel/test-timers-unrefed-in-callback.js

+let counter1 = 0;
+let counter2 = 0;
+
+// Test1 checks clearInterval also works fine for the unrefed timer


s/also// since it's now the first test in this tests suite.

misterdjules · 2017-03-06T18:44:11Z

test/parallel/test-timers-unrefed-in-callback.js

+
+// Test1 checks clearInterval also works fine for the unrefed timer
+// within timer callback. counter1 stops at exactly 11 with
+// clearInterval. This test should be executed at first to confirm


@shigeki

This test should be executed at first to confirm that timer1 is surly stopped in 10 msec while Test2 is running.

I think this description lacks some details and has some errors that prevent it from being easily understandable by someone not already familiar with this specific tests suite and the timers implementation.

Here's what I'd suggest as a replacement for the whole block of comment:

Test1 checks that clearInterval works as expected for a timer unrefed within its callback: it removes the timer and its callback is not called anymore. Note that the only reason why this test is robust is that: 1. the repeated timer it creates has a delay of 1ms 2. when this test is completed, another test starts that creates a new repeated timer with the same delay (1ms) 3. because of the way timers are implemented in libuv, if two repeated timers A and B are created in that order with the same delay, it is guaranteed that the first occurrence of timer A will fire before the first occurrence of timer B 4. as a result, when the timer created by Test2 fired 11 times, if the timer created by Test1 hadn't been removed by clearInterval, it would have fired 11 more times, and the assertion in the process' exit event handler would fail.

What do you think?

@misterdjules It describes much more details for Test1. There is no reason against for it. Fixed in dffeb3b97915ec3582205dfa883cac0aaf1f9ad4.

misterdjules

This is progressing well in my opinion. I think once my latest comments are addressed I should be able to approve this.

misterdjules

This LGTM, but we still need to:

run CI tests on the latest changes
make sure to squash all commits in this PR into one single commit if and before these changes land
make sure @Fishrock123 doesn't have any objection on the current state of this PR

Thank you for doing this!

The timer handle is reused when it is unrefed in order to avoid new callback in beforeExit(nodejs#3407). If it is unrefed within a setInterval callback, the reused timer handle is closed so that setInterval no longer keep working. This fix does not close the handle in case of setInterval.

shigeki · 2017-03-08T06:31:24Z

Squashed and CI is running on https://ci.nodejs.org/job/node-test-commit/8310/.

shigeki · 2017-03-08T06:54:45Z

CI results are all green. 1. and 2. are finished.

@Fishrock123 I need your comment or approval.

misterdjules · 2017-03-16T19:50:37Z

Ping @Fishrock123.

Fishrock123 · 2017-03-16T23:07:18Z

test/parallel/test-timers-unrefed-in-callback.js

+ const timer1 = setInterval(() => {
+ timer1.unref();
+ if (counter1++ === 10) {
+ clearInterval(timer1);


clearInterval works in a very specific way (in the end, it sets _idleTimeout = 0) and while it is affected in this problem it is unnecessary for testing it?

I intended to add the clearInterval test because it executes timer.close() and to check if it is not affected by this fix. I think it can prove this fix has no side effects on timer.close() during the use of unrefed setInterval.

Fishrock123 · 2017-03-16T23:07:53Z

test/parallel/test-timers-unrefed-in-callback.js

+}
+
+process.on('exit', () => {
+ assert.strictEqual(counter1, 11);


You should only need to do 3 intervals for either, regardless. That should be enough to prove it is functioning.

Okay, 10 is no meaning. Fixed to 3 intervals.

Fishrock123

New CI: https://ci.nodejs.org/job/node-test-pull-request/6976/

The timer handle is reused when it is unrefed in order to avoid new callback in beforeExit(#3407). If it is unrefed within a setInterval callback, the reused timer handle is closed so that setInterval no longer keep working. This fix does not close the handle in case of setInterval. PR-URL: #11646 Reviewed-By: Julien Gilli <jgilli@nodejs.org> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

jasnell · 2017-03-22T17:49:43Z

Landed in 81ab78e

The timer handle is reused when it is unrefed in order to avoid new callback in beforeExit(#3407). If it is unrefed within a setInterval callback, the reused timer handle is closed so that setInterval no longer keep working. This fix does not close the handle in case of setInterval. PR-URL: #11646 Reviewed-By: Julien Gilli <jgilli@nodejs.org> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

MylesBorins · 2017-04-18T20:13:51Z

was able to repro behavior on both v4 and v6

landed cleanly on v6, but requires a backport for v4... should we backport?

The timer handle is reused when it is unrefed in order to avoid new callback in beforeExit(#3407). If it is unrefed within a setInterval callback, the reused timer handle is closed so that setInterval no longer keep working. This fix does not close the handle in case of setInterval. PR-URL: #11646 Reviewed-By: Julien Gilli <jgilli@nodejs.org> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

shigeki · 2017-04-19T01:42:08Z

V4 has also this issue because of #3407 (comment). So I think this should be backported.

The patch in this PR has some conflicts in lib/timers.js. The equivalent fix is

diff --git a/lib/timers.js b/lib/timers.js
index 884c764..73cb70d 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -109,8 +109,14 @@ function listOnTimeout() {

   debug('%d list empty', msecs);
   assert(L.isEmpty(list));
-  list.close();
   delete lists[msecs];
+
+  // Do not close the underlying handle if its ownership has changed
+  // (e.g it was unrefed in its callback).
+  if (list.owner)
+    return;
+
+  list.close();
 }

The timer handle is reused when it is unrefed in order to avoid new callback in beforeExit(nodejs#3407). If it is unrefed within a setInterval callback, the reused timer handle is closed so that setInterval no longer keep working. This fix does not close the handle in case of setInterval. PR-URL: nodejs/node#11646 Reviewed-By: Julien Gilli <jgilli@nodejs.org> Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

nodejs-github-bot added the timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. label Mar 2, 2017

misterdjules reviewed Mar 2, 2017

View reviewed changes

Fishrock123 self-assigned this Mar 2, 2017

Fishrock123 self-requested a review March 2, 2017 21:44

misterdjules suggested changes Mar 2, 2017

View reviewed changes

Fishrock123 suggested changes Mar 2, 2017

View reviewed changes

misterdjules reviewed Mar 6, 2017

View reviewed changes

misterdjules suggested changes Mar 6, 2017

View reviewed changes

misterdjules approved these changes Mar 7, 2017

View reviewed changes

shigeki force-pushed the fix_unref_timer_setinterval branch from dffeb3b to 5462380 Compare March 8, 2017 06:16

Fishrock123 suggested changes Mar 16, 2017

View reviewed changes

test: descrease conuter to iterate

f497955

Fishrock123 approved these changes Mar 22, 2017

View reviewed changes

jasnell approved these changes Mar 22, 2017

View reviewed changes

jasnell closed this Mar 22, 2017

MylesBorins mentioned this pull request Mar 28, 2017

V7.8.0 proposal #12104

Merged

italoacasas mentioned this pull request Apr 10, 2017

v7.9.0 Release Proposal #12319

Merged

2 tasks

MylesBorins added land-on-v6.x labels Apr 18, 2017

MylesBorins added the backport-requested-v4.x label Apr 18, 2017

MylesBorins mentioned this pull request Apr 19, 2017

v6.10.3 proposal #12498

Merged

		@@ -0,0 +1,49 @@
		'use strict';
		// Check that unrefed setInterval timer keeps running even if it is

		@@ -232,6 +231,12 @@ function listOnTimeout() {
		} else if (list === refedLists[msecs]) {
		delete refedLists[msecs];

	// A convenience function for re-using TimerWrap handles more easily.
	//
	// This mostly exists to fix https://github.com/nodejs/node/issues/1264.
	// Handles in libuv take at least one `uv_run` to be registered as unreferenced.
	// Re-using an existing handle allows us to skip that, so that a second `uv_run`
	// will return no active handles, even when running `setTimeout(fn).unref()`.
	function reuse(item) {
	L.remove(item);

	var list = refedLists[item._idleTimeout];
	// if empty - reuse the watcher
	if (list && L.isEmpty(list)) {
	debug('reuse hit');
	list._timer.stop();
	delete refedLists[item._idleTimeout];
	return list._timer;
	}

	return null;
	}

timers: fix not to close reused timer handle #11646

timers: fix not to close reused timer handle #11646

Conversation

shigeki commented Mar 2, 2017

Checklist

Affected core subsystem(s)

shigeki commented Mar 2, 2017

Fishrock123 commented Mar 2, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

misterdjules left a comment

Choose a reason for hiding this comment

misterdjules commented Mar 2, 2017 • edited Loading

Fishrock123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

misterdjules Mar 3, 2017 • edited by gibfahn Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

misterdjules Mar 6, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

misterdjules left a comment

Choose a reason for hiding this comment

misterdjules left a comment

Choose a reason for hiding this comment

shigeki commented Mar 8, 2017

shigeki commented Mar 8, 2017

misterdjules commented Mar 16, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Fishrock123 left a comment

Choose a reason for hiding this comment

jasnell commented Mar 22, 2017

MylesBorins commented Apr 18, 2017

shigeki commented Apr 19, 2017

misterdjules commented Mar 2, 2017 •

edited

Loading

misterdjules Mar 3, 2017 •

edited by gibfahn

Loading

misterdjules Mar 6, 2017 •

edited

Loading