Skip to content

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

Closed
#37636
Closed
flaky: parallel/test-async-hooks-http-parser-destroy.js#26610
#37636
Labels
armIssues and PRs related to the ARM architecture.async_hooksIssues and PRs related to the async hooks subsystem.flaky-testIssues and PRs involving tests that fail intermittently in CI.

Description

@refack
refack
opened on 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);

Activity

  1. refack
    added
    flaky-testIssues and PRs involving tests that fail intermittently in CI.
    on Mar 12, 2019

  2. Trott commented on Mar 12, 2019

    @Trott
    Trott
    on Mar 12, 2019
    Member

    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   ...

  3. Trott commented on Mar 12, 2019

    @Trott
    Trott
    on Mar 12, 2019
    Member

    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   ...

  4. Trott commented on Mar 17, 2019

    @Trott
    Trott
    on Mar 17, 2019
    Member

    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   ...

  5. joyeecheung commented on Mar 22, 2019

    @joyeecheung
    joyeecheung
    on Mar 22, 2019
    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)
  ...
  6. joyeecheung
    added
    armIssues and PRs related to the ARM architecture.
    on Mar 22, 2019

  7. joyeecheung commented on Mar 22, 2019

    @joyeecheung
    joyeecheung
    on Mar 22, 2019
    Member

    Looks like this only happens on the pis

  8. Trott commented on Mar 24, 2019

    @Trott
    Trott
    on Mar 24, 2019
    Member

    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   ...

  9. Trott commented on Mar 28, 2019

    @Trott
    Trott
    on Mar 28, 2019
    Member

    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   ...

  10. Trott commented on Mar 28, 2019

    @Trott
    Trott
    on Mar 28, 2019
    Member

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

  11. Trott commented on Mar 28, 2019

    @Trott
    Trott
    on Mar 28, 2019
    Member

    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....

  12. Trott commented on Mar 28, 2019

    @Trott
    Trott
    on Mar 28, 2019
    Member

    (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...)

  13. Trott commented on Mar 28, 2019

    @Trott
    Trott
    on Mar 28, 2019
    Member

    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.

  14. refack commented on Apr 5, 2019

    @refack
    refack
    on Apr 5, 2019
    ContributorAuthor

    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/

  15. refack commented on Apr 5, 2019

    @refack
    refack
    on Apr 5, 2019
    ContributorAuthor

    And now on pi3 for the RPI tripecta

  16. Trott commented on Apr 6, 2019

    @Trott
    Trott
    on Apr 6, 2019
    Member

    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   ...
  17. refack
    added a commit that references this issue on Apr 11, 2019

    test: mark some known flakes

    abe4183
  18. Trott
    added a commit that references this issue on Apr 19, 2019

    test: simplify test-async-hooks-http-parser-destroy

    079d054
  19. sam-github
    added
    async_hooksIssues and PRs related to the async hooks subsystem.
    on Jun 7, 2019

  20. Trott commented on Sep 2, 2020

    @Trott
    Trott
    on Sep 2, 2020
    Member

    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   ...

  21. Trott commented on Sep 2, 2020

    @Trott
    Trott
    on Sep 2, 2020
    Member

    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

  22. Trott
    closed this as completedin 20009d7on Mar 8, 2021
  23. danielleadams
    added a commit that references this issue on Mar 16, 2021

    test: remove FLAKY status for test-async-hooks-http-parser-destroy

    1f63418
  24. targos
    added a commit that references this issue on May 1, 2021

    test: remove FLAKY status for test-async-hooks-http-parser-destroy

    376fcc7
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    armIssues and PRs related to the ARM architecture.async_hooksIssues and PRs related to the async hooks subsystem.flaky-testIssues and PRs involving tests that fail intermittently in CI.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions