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.

Sign up for GitHub

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

Jump to bottom

flaky: parallel/test-async-hooks-http-parser-destroy.js #26610

Closed
refack opened this issue Mar 12, 2019 · 16 comments · Fixed by #37636
Closed

flaky: parallel/test-async-hooks-http-parser-destroy.js #26610

refack opened this issue Mar 12, 2019 · 16 comments · Fixed by #37636
Labels
arm Issues and PRs related to the ARM platform. async_hooks Issues and PRs related to the async hooks subsystem. flaky-test Issues and PRs related to the tests with unstable failures on the CI.

Comments

@refack
Copy link
Contributor

refack commented Mar 12, 2019

Failed job
Worker: https://ci.nodejs.org/computer/test-requireio_mcollina-debian9-armv7l_pi2-1/
Test:

node/test/parallel/test-async-hooks-http-parser-destroy.js

Lines 42 to 43 in f2064df

createdIds.forEach((createdAsyncId) => {
assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0);

@refack refack added the flaky-test Issues and PRs related to the tests with unstable failures on the CI. label Mar 12, 2019
@refack refack mentioned this issue Mar 12, 2019
Closed
@Trott
Copy link
Member

Trott commented Mar 12, 2019

A second failure with that test on test-requireio_svincent-debian9-armv7l_pi2-3:

https://ci.nodejs.org/job/node-test-binary-arm/6797/RUN_SUBSET=1,label=pi2-docker/console

00:18:01 not ok 36 parallel/test-async-hooks-http-parser-destroy
00:18:01   ---
00:18:01   duration_ms: 10.739
00:18:01   severity: fail
00:18:01   exitcode: 1
00:18:01   stack: |-
00:18:01     assert.js:340
00:18:01         throw err;
00:18:01         ^
00:18:01     
00:18:01     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:18:01     
00:18:01       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
00:18:01     
00:18:01         at createdIds.forEach (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16)
00:18:01         at Array.forEach (<anonymous>)
00:18:01         at Timeout.setTimeout [as _onTimeout] (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
00:18:01         at listOnTimeout (timers.js:335:15)
00:18:01         at processTimers (timers.js:279:5)
00:18:01   ...

@Trott
Copy link
Member

Trott commented Mar 12, 2019

A third:

https://ci.nodejs.org/job/node-test-binary-arm/6792/RUN_SUBSET=1,label=pi2-docker/console

test-requireio_mcollina-debian9-armv7l_pi2-1

17:20:28 not ok 36 parallel/test-async-hooks-http-parser-destroy
17:20:28   ---
17:20:28   duration_ms: 11.536
17:20:28   severity: fail
17:20:28   exitcode: 1
17:20:28   stack: |-
17:20:28     assert.js:340
17:20:28         throw err;
17:20:28         ^
17:20:28     
17:20:28     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
17:20:28     
17:20:28       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
17:20:28     
17:20:28         at createdIds.forEach (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16)
17:20:28         at Array.forEach (<anonymous>)
17:20:28         at Timeout.setTimeout [as _onTimeout] (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
17:20:28         at listOnTimeout (timers.js:335:15)
17:20:28         at processTimers (timers.js:279:5)
17:20:28   ...

@Trott
Copy link
Member

Trott commented Mar 17, 2019

Fourth: https://ci.nodejs.org/job/node-test-binary-arm/6946/RUN_SUBSET=1,label=pi2-docker/console

test-requireio_mcollina-debian9-armv7l_pi2-1

00:12:34 ok 34 parallel/test-child-process-exec-stdout-stderr-data-string
00:12:34   ---
00:12:34   duration_ms: 2.536
00:12:34   ...
00:12:36 not ok 35 parallel/test-async-hooks-http-parser-destroy
00:12:36   ---
00:12:36   duration_ms: 10.285
00:12:36   severity: fail
00:12:37   exitcode: 1
00:12:37   stack: |-
00:12:37     assert.js:340
00:12:37         throw err;
00:12:37         ^
00:12:37     
00:12:37     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:12:37     
00:12:37       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
00:12:37     
00:12:37         at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
00:12:37         at Array.forEach (<anonymous>)
00:12:37         at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
00:12:37         at listOnTimeout (timers.js:335:15)
00:12:37         at processTimers (timers.js:279:5)
00:12:37   ...

Fifth: https://ci.nodejs.org/job/node-test-binary-arm/6946/RUN_SUBSET=1,label=pi3-docker/console

test-requireio_securogroup-debian9-arm64_pi3-2

00:12:14 not ok 41 parallel/test-async-hooks-http-parser-destroy
00:12:14   ---
00:12:14   duration_ms: 8.545
00:12:14   severity: fail
00:12:14   exitcode: 1
00:12:14   stack: |-
00:12:14     assert.js:340
00:12:14         throw err;
00:12:14         ^
00:12:14     
00:12:14     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:12:14     
00:12:14       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
00:12:14     
00:12:14         at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
00:12:14         at Array.forEach (<anonymous>)
00:12:14         at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
00:12:14         at listOnTimeout (timers.js:335:15)
00:12:14         at processTimers (timers.js:279:5)
00:12:14   ...

@joyeecheung joyeecheung mentioned this issue Mar 22, 2019
Closed
@joyeecheung
Copy link
Member

Recent data points:

Reason parallel/test-async-hooks-http-parser-destroy
Type JS_TEST_FAILURE
Failed PR 3 (#26810, #26739, #26805)
Appeared test-requireio_svincent-debian9-armv7l_pi2-2, test-requireio_rvagg-debian9-armv7l_pi2-1
First CI https://ci.nodejs.org/job/node-test-pull-request/21713/
Last CI https://ci.nodejs.org/job/node-test-pull-request/21766/
Example 
not ok 34 parallel/test-async-hooks-http-parser-destroy
  ---
  duration_ms: 10.849
  severity: fail
  exitcode: 1
  stack: |-
    assert.js:342
        throw err;
        ^
    
    AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
    
      assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
    
        at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
        at Array.forEach (<anonymous>)
        at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
        at listOnTimeout (internal/timers.js:535:17)
        at processTimers (internal/timers.js:479:7)
  ...

@joyeecheung joyeecheung added the arm Issues and PRs related to the ARM platform. label Mar 22, 2019
@joyeecheung
Copy link
Member

Looks like this only happens on the pis

@gireeshpunathil gireeshpunathil mentioned this issue Mar 23, 2019
Merged
4 tasks
@Trott
Copy link
Member

Trott commented Mar 24, 2019

https://ci.nodejs.org/job/node-test-binary-arm/7110/RUN_SUBSET=3,label=pi2-docker/console

test-requireio_svincent-debian9-armv7l_pi2-2

00:15:40 not ok 35 parallel/test-async-hooks-http-parser-destroy
00:15:40   ---
00:15:40   duration_ms: 10.990
00:15:40   severity: fail
00:15:40   exitcode: 1
00:15:40   stack: |-
00:15:40     assert.js:343
00:15:40         throw err;
00:15:40         ^
00:15:40     
00:15:40     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:15:40     
00:15:40       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
00:15:40     
00:15:40         at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
00:15:40         at Array.forEach (<anonymous>)
00:15:40         at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
00:15:40         at listOnTimeout (internal/timers.js:535:17)
00:15:40         at processTimers (internal/timers.js:479:7)
00:15:40   ...

@Trott
Copy link
Member

Trott commented Mar 28, 2019

https://ci.nodejs.org/job/node-test-binary-arm/7250/RUN_SUBSET=3,label=pi1-docker/console

test-requireio_bengl-debian9-armv6l_pi1p-2

00:19:48 not ok 24 parallel/test-async-hooks-http-parser-destroy
00:19:48   ---
00:19:48   duration_ms: 14.124
00:19:48   severity: fail
00:19:48   exitcode: 1
00:19:48   stack: |-
00:19:48     assert.js:343
00:19:48         throw err;
00:19:48         ^
00:19:48     
00:19:48     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:19:48     
00:19:48       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
00:19:48     
00:19:48         at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
00:19:48         at Array.forEach (<anonymous>)
00:19:48         at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
00:19:48         at listOnTimeout (internal/timers.js:535:17)
00:19:48         at processTimers (internal/timers.js:479:7)
00:19:48   ...

@Trott
Copy link
Member

Trott commented Mar 28, 2019

The test takes a bit longer to run than most other tests in parallel. I wonder if it can be dialed back a bit.

@Trott
Copy link
Member

Trott commented Mar 28, 2019

Yes, definitely room to dial it down a lot and still have it fail on the regression it is meant to test for. Experimenting a bit and will open a PR soon....

@Trott
Copy link
Member

Trott commented Mar 28, 2019

(Although I guess maybe not since that probably doesn't explain why this is failing on the Pi's? Maybe it will become obvious while refactoring...)

@Trott
Copy link
Member

Trott commented Mar 28, 2019 •
edited
Loading

Looks like the destroy callback for some ids can be called more than once. That seems like a bug. Opened #26961 and will use a Set for now to work around the problem.

@Trott Trott mentioned this issue Mar 28, 2019
Closed
2 tasks
@refack
Copy link
Contributor Author

refack commented Apr 5, 2019 •
edited
Loading

https://ci.nodejs.org/job/node-test-binary-arm/7440/RUN_SUBSET=2,label=pi2-docker/testReport/

test.parallel/test-async-hooks-http-parser-destroy
assert.js:343
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)

    at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
    at Array.forEach (<anonymous>)
    at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
    at listOnTimeout (internal/timers.js:537:17)
    at processTimers (internal/timers.js:481:7)

Worker: https://ci.nodejs.org/computer/test-requireio_rvagg-debian9-armv7l_pi2-1/

@refack
Copy link
Contributor Author

refack commented Apr 5, 2019

And now on pi3 for the RPI tripecta

@Trott
Copy link
Member

Trott commented Apr 6, 2019

https://ci.nodejs.org/job/node-test-binary-arm/7464/RUN_SUBSET=2,label=pi3-docker/console

test-requireio_pivotalagency-debian9-arm64_pi3-2

00:07:12 not ok 38 parallel/test-async-hooks-http-parser-destroy
00:07:12   ---
00:07:12   duration_ms: 10.441
00:07:12   severity: fail
00:07:12   exitcode: 1
00:07:12   stack: |-
00:07:12     assert.js:343
00:07:12         throw err;
00:07:12         ^
00:07:12     
00:07:12     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:07:12     
00:07:12       assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)
00:07:12     
00:07:12         at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:43:16
00:07:12         at Array.forEach (<anonymous>)
00:07:12         at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-async-hooks-http-parser-destroy.js:42:18)
00:07:12         at listOnTimeout (internal/timers.js:537:17)
00:07:12         at processTimers (internal/timers.js:481:7)
00:07:12   ...

@refack refack mentioned this issue Apr 11, 2019
Merged
4 tasks
refack added a commit to refack/node that referenced this issue Apr 11, 2019
@refack
test: mark some known flakes
abe4183 
PR-URL: nodejs#27193
Refs: nodejs#20750
Refs: nodejs#26610
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
Trott added a commit to Trott/io.js that referenced this issue Apr 19, 2019
@Trott
test: simplify test-async-hooks-http-parser-destroy
079d054 
Simplify test-async-hooks-http-parser-destroy and improve it's reporting
when failing. (Also makes it easier to run on older versions of Node.js
because it doesn't rely on internal test modules that won't work there.)

Before, failures looked like this (edited slightly to conform to our
commit message 72-char line length restriction):

    The expression evaluated to a falsy value:
    assert.ok(destroyedIds.indexOf(createdAsyncId) >= 0)

Now, you get a slightly better idea of what's up. (Is it missing one ID?
More than one? All of them?):

    Input A expected to strictly deep-equal input B:
    + expected - actual ... Lines skipped

      Set {
        1009,
    ...
        1025,
    -   158,
    -   159,
    -   161,
    -   162,
    -   164,
    -   165,
    -   167,
    -   168,
    -   170,
    ...
    +   159,
    +   162,
    +   165,
    +   168,
    +   171,
    +   174,
    +   177,
    +   180,
    +   183,

This test still fails as expected on 10.14.1 and passees on 10.14.2
(where the regression it tests for was fixed). (You will need to comment
on the `require('../common');` line first but that's now the only change
you need to make this run in older versions.)

Refs: nodejs#26610
@sam-github sam-github added the async_hooks Issues and PRs related to the async hooks subsystem. label Jun 7, 2019
@Trott
Copy link
Member

Trott commented Sep 2, 2020

I don't think the error above has shown up in a long time but the test did time out in CI on win2012r2/vs2019.

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/5584/RUN_SUBSET=0,nodes=win2012r2-COMPILED_BY-vs2019-x86/console

00:28:42 not ok 750 parallel/test-async-hooks-http-parser-destroy
00:28:42   ---
00:28:42   duration_ms: 120.143
00:28:42   severity: fail
00:28:42   exitcode: 1
00:28:42   stack: |-
00:28:42     timeout
00:28:42   ...

@Trott
Copy link
Member

Trott commented Sep 2, 2020

I don't think the error above has shown up in a long time but the test did time out in CI on win2012r2/vs2019.

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/5584/RUN_SUBSET=0,nodes=win2012r2-COMPILED_BY-vs2019-x86/console

00:28:42 not ok 750 parallel/test-async-hooks-http-parser-destroy
00:28:42   ---
00:28:42   duration_ms: 120.143
00:28:42   severity: fail
00:28:42   exitcode: 1
00:28:42   stack: |-
00:28:42     timeout
00:28:42   ...

There is code in the test to handle SIGTERM from a timeout so that we could theoretically get some information about what is going on, but alas, I don't think that works on Windows.

process.on('SIGTERM', () => {
  // Catching SIGTERM and calling `process.exit(1)` so that the `exit` event
  // is triggered and the assertions are checked. This can be useful for
  // troubleshooting this test if it times out.
  process.exit(1);
});

Thoughts on what to do instead? I'd rather not sprinkle console.log() everywhere or put a timer inside the test, but I guess we could do that temporarily. @nodejs/platform-windows

Trott added a commit to Trott/io.js that referenced this issue Mar 6, 2021
@Trott
test: remove FLAKY status for test-async-hooks-http-parser-destroy
0301d3b 
This CI test failure hasn't been reported for some time.

Closes: nodejs#26610
@Trott Trott mentioned this issue Mar 6, 2021
Merged
@Trott Trott closed this as completed in 20009d7 Mar 8, 2021
danielleadams pushed a commit that referenced this issue Mar 16, 2021
@Trott @danielleadams
test: remove FLAKY status for test-async-hooks-http-parser-destroy
1f63418 
This CI test failure hasn't been reported for some time.

Closes: #26610

PR-URL: #37636
Fixes: #26610
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
targos pushed a commit that referenced this issue May 1, 2021
@Trott @targos
test: remove FLAKY status for test-async-hooks-http-parser-destroy
376fcc7 
This CI test failure hasn't been reported for some time.

Closes: #26610

PR-URL: #37636
Fixes: #26610
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
arm Issues and PRs related to the ARM platform. async_hooks Issues and PRs related to the async hooks subsystem. flaky-test Issues and PRs related to the tests with unstable failures on the CI.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

test: remove FLAKY status for test-async-hooks-http-parser-destroy Trott/io.js
4 participants
@sam-github @refack @Trott @joyeecheung