Unreferenced timers run during beforeExit timeframe

[brycebaril]

Cross-posting from nodejs/node#1264

The gist of the problem is the beforeExit implementation causes inconsistent and racy situations in timers when the application is closing, a race which can result in an application failing to close and hanging on unreferenced timers. Unreferenced timers will be executed when they shouldn't have been, and will keep the application alive longer as a result.

Sample code:

var assert = require("assert")
var intervals = 0
var i = setInterval(function () {
  intervals++
  i.unref()
  eatTime()
}, 10)

function eatTime() {
  // the goal of this function is to take longer than the interval
  var count = 0
  while (count++ < 1e7) {
    Math.random()
  }
}

process.on("exit", function () {
  assert.equal(intervals, 1)
})

0.12.1:

bryce@x220:/tmp$ node -v
v0.12.1
bryce@x220:/tmp$ node ah14.js

assert.js:86
  throw new assert.AssertionError({
        ^
AssertionError: 3 == 1
    at process.<anonymous> (/tmp/ah14.js:17:10)
    at process.emit (events.js:107:17)

0.10.38

bryce@x220:/tmp$ node -v
v0.10.38
bryce@x220:/tmp$ node ah14.js 
bryce@x220:/tmp$ 

This impacts 0.11.12 and higher, including 0.12.0 and 0.12.1.

It works as expected in 0.10 (which has no beforeExit)

[misterdjules]

Thanks for reporting this issue here!

The reproduction code adds a listener on 'exit', not on 'beforeExit', is that intentional or a typo?
Also, it seems there are (at least) two separate issues described in nodejs/node#1264.

1. node doesn't exit when running this code as mentioned by @trevnorris:
   process.on('beforeExit', function() { setInterval(function() {}, 1).unref(); });

2. The interval's callback is called more than once with this code:

var assert = require("assert")
var intervals = 0
var i = setInterval(function () {
  intervals++
  i.unref()
  eatTime()
}, 10)

function eatTime() {
  // the goal of this function is to take longer than the interval
  var count = 0
  while (count++ < 1e7) {
    Math.random()
  }
}

process.on("exit", function () {
  assert.equal(intervals, 1)
})

My understanding is that these two issues can be fixed separately, and that it would help to have two separate issues for them. Am I correct or am I missing something?

[Fishrock123]

The reproduction code adds a listener on 'exit', not on 'beforeExit', is that intentional or a typo?

The placement of the assertion is intentional.

My understanding is that these two issues can be fixed separately, and that it would help to have two separate issues for them. Am I correct or am I missing something?

Due to some of my digging in nodejs/node#1152 (port of the original unref leak fix) that was suggested to fix nodejs/node#1151 does not actually), we've unearthed several test cases where things go pretty banannas (see: nodejs/node#1191).

As mentioned in the cross-posted issue, @bnoordhuis is working on a re-write, because the timers module is pretty incomprehensible.

[misterdjules]

The reproduction code adds a listener on 'exit', not on 'beforeExit', is that intentional or a typo?

The placement of the assertion is intentional.

The description of this issue mentions that "The gist of the problem is the beforeExit implementation", but the reproduction code doesn't add any listener on the beforeExit event, hence my question.

[Fishrock123]

The description of this issue mentions that "The gist of the problem is the beforeExit implementation", but the reproduction code doesn't add any listener on the beforeExit event, hence my question.

I think the situation ended up being that the timer ends up re-running during the beforeExit phase. (to my understanding)

[misterdjules]

@Fishrock123 My understanding is that the problem for issue 1) is in the way Node.js uses uv_run and how uv_run runs timers in this use case, but it's not specific to the way the beforeExit event is implemented.

Issue 2) seems to be related specifically to the fact that there's no mechanism in place to make sure EmitBeforeExit is called only once, including that it's not called indefinitely.

[brycebaril]

@misterdjules the issue is caused by the beforeExit commit a2eeb43 (found via @trevnorris doing git bisect)

No beforeExit event exists in my example, but the check to see if there is more pending work to be done immediately after the beforeExit event is emit has no check to see if it came from a beforeExit event handler, nor a check if that work was unref'd and therefore shouldn't be run.

What I meant by "beforeExit timeframe" was the application timeframe when beforeExit is invoked, not during a beforeExit emit specifically.

[misterdjules]

@brycebaril OK yes, I see what you mean now, and thank you for the clarification.

It was introduced by that commit, but specifically by the use of UV_RUN_ONCE. Here's a gist where we can see the impact of different uv_run modes on this issue.

[brycebaril]

@misterdjules great research! Thanks for the gist

[misterdjules]

I'm available to guide anyone willing to pick this issue up and submit a PR that fixes it. Ping me on GitHub by mentioning @misterdjules or find me on IRC (jgi in #libuv on Freenode).

EDIT: I'm also available by email at jgilli at fastmail dot fm.

[misterdjules]

This issue is now tracked by nodejs/node#1264, so closing to avoid confusion.

[whitlockjc]

Thanks @misterdjules. 👍