investigate flaky test-timers-blocking-callback #21781

Trott · 2018-07-12T17:48:11Z

Version: 11.0.0-pre (master)
Platform: osx1012
Subsystem: test timers

https://ci.nodejs.org/job/node-test-commit-osx/19771/nodes=osx1012/console

13:09:28 not ok 2336 sequential/test-timers-blocking-callback
13:09:28   ---
13:09:28   duration_ms: 2.270
13:09:28   severity: fail
13:09:28   exitcode: 1
13:09:28   stack: |-
13:09:28     assert.js:80
13:09:28       throw new AssertionError(obj);
13:09:28       ^
13:09:28     
13:09:28     AssertionError [ERR_ASSERTION]: timeout delayed by more than 100% (230ms)
13:09:28         at blockingCallback (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/test/sequential/test-timers-blocking-callback.js:62:14)
13:09:28         at ontimeout (timers.js:457:11)
13:09:28         at tryOnTimeout (timers.js:327:5)
13:09:28         at listOnTimeout (timers.js:301:5)
13:09:28         at processTimers (timers.js:258:5)
13:09:28   ...

Trott · 2018-07-15T02:44:26Z

Happened again today.

https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1012/19834/console

20:24:08 not ok 2340 sequential/test-timers-blocking-callback
20:24:08   ---
20:24:08   duration_ms: 2.301
20:24:08   severity: fail
20:24:08   exitcode: 1
20:24:08   stack: |-
20:24:08     assert.js:80
20:24:08       throw new AssertionError(obj);
20:24:08       ^
20:24:08     
20:24:08     AssertionError [ERR_ASSERTION]: timeout delayed by more than 100% (250ms)
20:24:08         at blockingCallback (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/test/sequential/test-timers-blocking-callback.js:62:14)
20:24:08         at ontimeout (timers.js:457:11)
20:24:08         at tryOnTimeout (timers.js:327:5)
20:24:08         at listOnTimeout (timers.js:301:5)
20:24:08         at processTimers (timers.js:258:5)
20:24:08   ...

apapirovski · 2018-07-15T17:03:31Z

@Trott Given that this only fails on macOS 10.12, I wonder if there's either something weird about the setup of that system or a bug in the OS itself. FWIW I'm on 10.12.6 and can't get this test to fail even in parallel with -j 96 --repeat 960.

Also, the duration of the run when it fails (2.3s) indicates that something weird is happening on that machine. This test normally takes significantly less time.

Trott · 2018-07-15T20:57:57Z

@apapirovski For what it's worth, since the test is in sequential, the -j 96 won't really affect it. If you want to test under load, move it to parallel and run that version with -j 96 --repeat 960 (or whatever).

apapirovski · 2018-07-16T00:00:29Z

@Trott yes, that is what I did to test it.

Trott · 2018-07-16T01:09:31Z

@Trott yes, that is what I did to test it.

Oooooohhhhhh...yeah, in that case...I'm not seeing it fail that way either, so this is probably something other than mere load (like maybe one of the two possibilities you suggest, of course)

Trott · 2018-07-30T17:49:34Z

Again today: https://ci.nodejs.org/job/node-test-commit-osx/20095/nodes=osx1012/console

04:20:50 not ok 2354 sequential/test-timers-blocking-callback
04:20:50   ---
04:20:50   duration_ms: 1.755
04:20:50   severity: fail
04:20:50   exitcode: 1
04:20:50   stack: |-
04:20:50     assert.js:84
04:20:50       throw new AssertionError(obj);
04:20:50       ^
04:20:50     
04:20:50     AssertionError [ERR_ASSERTION]: timeout delayed by more than 100% (250ms)
04:20:50         at blockingCallback (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1012/test/sequential/test-timers-blocking-callback.js:62:14)
04:20:50         at ontimeout (timers.js:454:11)
04:20:50         at tryOnTimeout (timers.js:326:5)
04:20:50         at listOnTimeout (timers.js:300:5)
04:20:50         at processTimers (timers.js:257:5)
04:20:50   ...

Trott · 2018-07-30T17:50:20Z

FWIW, the 10.12 machines in CI are relatively small machines (I believe 3GHz 2-core 4GB RAM) so maybe that's part of what's going on?

Trott · 2018-07-30T17:50:40Z

@nodejs/platform-macos

apapirovski · 2018-07-31T15:24:28Z

I'm still completely stumped by this. I might have to request access to one of these machines to make further progress.

Fishrock123 · 2018-08-07T15:46:38Z

I'm not sure either.

That being said, with the most recent timers refactor, is this test still relevant?

apapirovski · 2018-08-07T15:47:53Z

@Fishrock123 not super relevant but probably worth keeping around depending on how the architecture evolves, right? I'll try to get access later this week and see what's going on.

MylesBorins · 2020-03-11T02:33:33Z

Back from the dead

https://ci.nodejs.org/job/node-test-commit-osx/32536/nodes=osx1015/testReport/junit/(root)/test/sequential_test_timers_blocking_callback/

assert.js:141
  throw err;
  ^

AssertionError [ERR_ASSERTION]: timeout delayed by more than 100% (224ms)
    at blockingCallback (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/sequential/test-timers-blocking-callback.js:64:14)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: undefined,
  expected: undefined,
  operator: 'fail'
}

This is only for 10.15 but this test is periodically failing across many CI runs. Would like to mark this as flaky so we can avoid lots of red CI. Refs: nodejs#21781

This is only for 10.15 but this test is periodically failing across many CI runs. Would like to mark this as flaky so we can avoid lots of red CI. Refs: #21781 PR-URL: #32189 Reviewed-By: Gireesh Punathil <[email protected]> Reviewed-By: Beth Griggs <[email protected]>

Fishrock123 · 2020-04-12T21:08:21Z

Does changing Date.now() to internalBinding('timers').getLibuvNow make any difference here?

Fishrock123 · 2020-04-12T21:11:17Z

Also, does this always happen on macOs 10.15 now?

This is only for 10.15 but this test is periodically failing across many CI runs. Would like to mark this as flaky so we can avoid lots of red CI. Refs: #21781 PR-URL: #32189 Reviewed-By: Gireesh Punathil <[email protected]> Reviewed-By: Beth Griggs <[email protected]>

If the bug this test is intented to catch is reintroduced, or if 5aac4c4 is effectively reverted, many (50+) tests time out, rendering this test redundant and unnecessary. in particular, the following timer tests catch an effective revert of 5aac4c4: not ok 21 parallel/test-timers-api-refs not ok 22 parallel/test-timers-args not ok 23 parallel/test-timers-destroyed not ok 25 parallel/test-timers-nested not ok 26 parallel/test-timers-interval-throw not ok 28 parallel/test-timers-non-integer-delay not ok 32 parallel/test-timers-ordering not ok 33 parallel/test-timers-refresh not ok 34 parallel/test-timers-refresh-in-callback not ok 35 parallel/test-timers-reset-process-domain-on-throw not ok 40 parallel/test-timers-timeout-to-interval not ok 41 parallel/test-timers-uncaught-exception not ok 42 parallel/test-timers-timeout-with-non-integer not ok 43 parallel/test-timers-unenroll-unref-interval not ok 44 parallel/test-timers-unref not ok 45 parallel/test-timers-unref-active not ok 46 parallel/test-timers-unrefd-interval-still-fires not ok 47 parallel/test-timers-unrefed-in-callback not ok 48 parallel/test-timers-user-call not ok 49 parallel/test-timers-zero-timeout Refs: nodejs#21781

Trott · 2020-04-26T05:25:07Z

Fixed in f8d5474

If the bug this test is intented to catch is reintroduced, or if 5aac4c4 is effectively reverted, many (50+) tests time out, rendering this test redundant and unnecessary. in particular, the following timer tests catch an effective revert of 5aac4c4: not ok 21 parallel/test-timers-api-refs not ok 22 parallel/test-timers-args not ok 23 parallel/test-timers-destroyed not ok 25 parallel/test-timers-nested not ok 26 parallel/test-timers-interval-throw not ok 28 parallel/test-timers-non-integer-delay not ok 32 parallel/test-timers-ordering not ok 33 parallel/test-timers-refresh not ok 34 parallel/test-timers-refresh-in-callback not ok 35 parallel/test-timers-reset-process-domain-on-throw not ok 40 parallel/test-timers-timeout-to-interval not ok 41 parallel/test-timers-uncaught-exception not ok 42 parallel/test-timers-timeout-with-non-integer not ok 43 parallel/test-timers-unenroll-unref-interval not ok 44 parallel/test-timers-unref not ok 45 parallel/test-timers-unref-active not ok 46 parallel/test-timers-unrefd-interval-still-fires not ok 47 parallel/test-timers-unrefed-in-callback not ok 48 parallel/test-timers-user-call not ok 49 parallel/test-timers-zero-timeout Refs: #21781 PR-URL: #32870 Reviewed-By: Anatoli Papirovski <[email protected]> Reviewed-By: Michaël Zasso <[email protected]> Reviewed-By: Rich Trott <[email protected]>

Trott added timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. macos Issues and PRs related to the macOS platform / OSX. flaky-test Issues and PRs related to the tests with unstable failures on the CI. labels Jul 12, 2018

Trott mentioned this issue Jul 12, 2018

repl: make own properties shadow prototype properties #21588

Closed

3 tasks

apapirovski self-assigned this Jul 13, 2018

Trott mentioned this issue Jul 15, 2018

tools: update ESLint to 5.2.0 #21817

Closed

3 tasks

apapirovski closed this as completed Oct 18, 2018

MylesBorins reopened this Mar 11, 2020

MylesBorins mentioned this issue Mar 11, 2020

test: mark test-timers-blocking-callback flaky on osx #32189

Closed

mmarchini mentioned this issue Mar 11, 2020

deps: update V8 to 8.1 #32116

Closed

15 tasks

Fishrock123 mentioned this issue Apr 15, 2020

test: remove timers-blocking-callback #32870

Closed

3 tasks

Trott closed this as completed Apr 26, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

investigate flaky test-timers-blocking-callback #21781

investigate flaky test-timers-blocking-callback #21781

Trott commented Jul 12, 2018

Trott commented Jul 15, 2018

apapirovski commented Jul 15, 2018 •

edited

Loading

Trott commented Jul 15, 2018

apapirovski commented Jul 16, 2018

Trott commented Jul 16, 2018 •

edited

Loading

Trott commented Jul 30, 2018

Trott commented Jul 30, 2018

Trott commented Jul 30, 2018

apapirovski commented Jul 31, 2018

Fishrock123 commented Aug 7, 2018

apapirovski commented Aug 7, 2018

MylesBorins commented Mar 11, 2020

Fishrock123 commented Apr 12, 2020

Fishrock123 commented Apr 12, 2020

Trott commented Apr 26, 2020 •

edited

Loading

investigate flaky test-timers-blocking-callback #21781

investigate flaky test-timers-blocking-callback #21781

Comments

Trott commented Jul 12, 2018

Trott commented Jul 15, 2018

apapirovski commented Jul 15, 2018 • edited Loading

Trott commented Jul 15, 2018

apapirovski commented Jul 16, 2018

Trott commented Jul 16, 2018 • edited Loading

Trott commented Jul 30, 2018

Trott commented Jul 30, 2018

Trott commented Jul 30, 2018

apapirovski commented Jul 31, 2018

Fishrock123 commented Aug 7, 2018

apapirovski commented Aug 7, 2018

MylesBorins commented Mar 11, 2020

Fishrock123 commented Apr 12, 2020

Fishrock123 commented Apr 12, 2020

Trott commented Apr 26, 2020 • edited Loading

apapirovski commented Jul 15, 2018 •

edited

Loading

Trott commented Jul 16, 2018 •

edited

Loading

Trott commented Apr 26, 2020 •

edited

Loading