Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

test: investigate failing test-timers-unrefed-in-beforeexit #18047

Closed
jasnell opened this issue Jan 8, 2018 · 12 comments
Closed

test: investigate failing test-timers-unrefed-in-beforeexit #18047

jasnell opened this issue Jan 8, 2018 · 12 comments
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout.

Comments

@jasnell
Copy link
Member

jasnell commented Jan 8, 2018

parallel/test-timers-unrefed-in-beforeexit is suddenly failing in CI:
https://ci.nodejs.org/job/node-test-commit-linux/15434/nodes=alpine35-container-x64/console

not ok 1526 parallel/test-timers-unrefed-in-beforeexit
  ---
  duration_ms: 0.217
  severity: fail
  stack: |-
    assert.js:43
      throw new errors.AssertionError(obj);
      ^
    
    AssertionError [ERR_ASSERTION]: function should not have been called at /home/iojs/build/workspace/node-test-commit-linux/nodes/alpine35-container-x64/test/parallel/test-timers-unrefed-in-beforeexit.js:6
        at Timeout.mustNotCall [as _onTimeout] (/home/iojs/build/workspace/node-test-commit-linux/nodes/alpine35-container-x64/test/common/index.js:595:12)
        at ontimeout (timers.js:450:11)
        at Timer.unrefdHandle (timers.js:527:5)
  ...

@AndreasMadsen ... could this, by any chance, have anything to do with #18005?

@addaleax addaleax added timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. flaky-test Issues and PRs related to the tests with unstable failures on the CI. labels Jan 8, 2018
@addaleax
Copy link
Member

addaleax commented Jan 8, 2018

I think the test is flaky the way it is written anyway, 1ms might just be too short to make sure the event loop iteration is finished before the timer runs.

I guess increasing the timeout value to some much larger number should be okay, the test should still exit immediately.

@AndreasMadsen
Copy link
Member

@jasnell I don't think so, #18005 should only change process.exit() and that isn't called anywhere here.

@jasnell
Copy link
Member Author

jasnell commented Jan 8, 2018

Interesting... there's really nothing that I can see that would trigger this to be failing all of a sudden. I'm adding a commit in the PR where I'm seeing the failure that extends the timeout a bit. We'll see what happens :-)

@jasnell
Copy link
Member Author

jasnell commented Jan 8, 2018

Ugh. Ok, setting the timeout up to 10 causes the test to fail with a different error ... specifically, beforeExit is called twice instead of just once. Hmm.

@Fishrock123
Copy link
Contributor

Ugh. Ok, setting the timeout up to 10 causes the test to fail with a different error ... specifically, beforeExit is called twice instead of just once. Hmm.

Are you sure that this is what you did? It passes for me irrespective the duration.

The only way that could happen is if reuse() was broken, but I think there is more than one test which covers that?

@Fishrock123
Copy link
Contributor

We should just be able to set it to require('internal/timers').TIMEOUT_MAX... I'll make a PR.

@apapirovski
Copy link
Member

@Fishrock123 I don't think that's necessary. The failure has to do with the http2 binding.

@Fishrock123
Copy link
Contributor

You mean the HTTP2 binding is keeping the loop alive? What's the parent issue for this?

@Fishrock123
Copy link
Contributor

Fishrock123 commented Jan 8, 2018

Parent issue: #18020

(Please look for other instances of the same test failure in the future! 😉)

@jasnell
Copy link
Member Author

jasnell commented Jan 9, 2018

Will close this as it does appear to be an issue in the referenced PR... though certainly not an obvious one.

@jasnell jasnell closed this as completed Jan 9, 2018
@apapirovski
Copy link
Member

This is a legitimate bug although the test that it affects doesn't make the cause obvious (and http2 is a slight red herring). I've got a PR coming up.

@jasnell
Copy link
Member Author

jasnell commented Jan 9, 2018

Wow. Nice catch

@jasnell jasnell closed this as completed in ececdd3 Jan 9, 2018
jasnell pushed a commit to jasnell/node that referenced this issue Jan 9, 2018
Scheduling a PerformanceGCCallback should not keep the
loop alive but due to the recent switch to using the
native SetImmediate method, it does. Go back to using
uv_async_t and add a regression test.

PR-URL: nodejs#18051
Fixes: nodejs#18047
Refs: nodejs#18020
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
MylesBorins pushed a commit that referenced this issue Jan 9, 2018
Scheduling a PerformanceGCCallback should not keep the
loop alive but due to the recent switch to using the
native SetImmediate method, it does. Go back to using
uv_async_t and add a regression test.

Backport-PR-URL: #18050
PR-URL: #18051
Fixes: #18047
Refs: #18020
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
MylesBorins pushed a commit that referenced this issue Jan 10, 2018
Scheduling a PerformanceGCCallback should not keep the
loop alive but due to the recent switch to using the
native SetImmediate method, it does. Go back to using
uv_async_t and add a regression test.

Backport-PR-URL: #18050
PR-URL: #18051
Fixes: #18047
Refs: #18020
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
MylesBorins pushed a commit that referenced this issue May 22, 2018
Scheduling a PerformanceGCCallback should not keep the
loop alive but due to the recent switch to using the
native SetImmediate method, it does. Go back to using
uv_async_t and add a regression test.

PR-URL: #18051
Fixes: #18047
Refs: #18020
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
MylesBorins pushed a commit that referenced this issue Jun 14, 2018
Scheduling a PerformanceGCCallback should not keep the
loop alive but due to the recent switch to using the
native SetImmediate method, it does. Go back to using
uv_async_t and add a regression test.

PR-URL: #18051
Fixes: #18047
Refs: #18020
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
rvagg pushed a commit that referenced this issue Aug 16, 2018
Scheduling a PerformanceGCCallback should not keep the
loop alive but due to the recent switch to using the
native SetImmediate method, it does. Go back to using
uv_async_t and add a regression test.

PR-URL: #18051
Fixes: #18047
Refs: #18020
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants