Skip to content

Investigate flaky async-hooks/test-statwatcher #21425

Closed
#29392
Closed
Investigate flaky async-hooks/test-statwatcher#21425
#29392
Labels
async_hooksIssues and PRs related to the async hooks subsystem.flaky-testIssues and PRs involving tests that fail intermittently in CI.linuxIssues and PRs related to the Linux platform.windowsIssues and PRs related to the Windows platform.

Description

@Trott
Trott
opened on Jun 20, 2018
  • Version: v11.0.0-pre (master)
  • Platform: win2016 (vs2017)
  • Subsystem: async_hooks

https://ci.nodejs.org/job/node-test-binary-windows/18119/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=0/console

00:59:50 not ok 12 async-hooks/test-statwatcher
00:59:50   ---
00:59:50   duration_ms: 0.468
00:59:50   severity: fail
00:59:50   exitcode: 1
00:59:50   stack: |-
00:59:50     assert.js:80
00:59:50       throw new AssertionError(obj);
00:59:50       ^
00:59:50     
00:59:50     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
00:59:50          Called "before" 2 time(s), but expected 1 invocation(s).
00:59:50         at checkHook (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2017\RUNNER\win2016\RUN_SUBSET\0\test\async-hooks\hook-checks.js:51:14)
00:59:50         at Array.forEach (<anonymous>)
00:59:50         at checkInvocations (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2017\RUNNER\win2016\RUN_SUBSET\0\test\async-hooks\hook-checks.js:28:62)
00:59:50         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2017\RUNNER\win2016\RUN_SUBSET\0\test\async-hooks\test-statwatcher.js:65:9)
00:59:50         at runCallback (timers.js:678:18)
00:59:50         at tryOnImmediate (timers.js:649:5)
00:59:50         at processImmediate (timers.js:631:5)
00:59:50   ...

Activity

  1. Trott
    added
    windowsIssues and PRs related to the Windows platform.
    async_hooksIssues and PRs related to the async hooks subsystem.
    flaky-testIssues and PRs involving tests that fail intermittently in CI.
    on Jun 20, 2018

  2. Trott commented on Jun 20, 2018

    @Trott
    Trott
    on Jun 20, 2018
    MemberAuthor

    @nodejs/async_hooks @thlorenz

  3. Trott commented on Jun 26, 2018

    @Trott
    Trott
    on Jun 26, 2018
    MemberAuthor

    Again on the same platform:
    https://ci.nodejs.org/job/node-test-binary-windows/18237/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=0/console

    16:00:10 not ok 12 async-hooks/test-statwatcher
16:00:10   ---
16:00:10   duration_ms: 0.452
16:00:10   severity: fail
16:00:10   exitcode: 1
16:00:10   stack: |-
16:00:10     assert.js:80
16:00:10       throw new AssertionError(obj);
16:00:10       ^
16:00:10     
16:00:10     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
16:00:10          Called "before" 2 time(s), but expected 1 invocation(s).
16:00:10         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
16:00:10         at Array.forEach (<anonymous>)
16:00:10         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
16:00:10         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
16:00:10         at runCallback (timers.js:664:18)
16:00:10         at tryOnImmediate (timers.js:635:5)
16:00:10         at processImmediate (timers.js:617:5)
16:00:10   ...

    @nodejs/testing

  4. refack commented on Jul 26, 2018

    @refack
    refack
    on Jul 26, 2018
    Contributor

    https://ci.nodejs.org/job/node-test-binary-windows/18759/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=2/console

    So it seems like this happens only on the win2016 platform

  5. Trott commented on Jul 30, 2018

    @Trott
    Trott
    on Jul 30, 2018
    MemberAuthor

    win2016 yet again...

    https://ci.nodejs.org/job/node-test-binary-windows/18808/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=2/console

    00:41:05 not ok 12 async-hooks/test-statwatcher
00:41:05   ---
00:41:05   duration_ms: 0.468
00:41:05   severity: fail
00:41:05   exitcode: 1
00:41:05   stack: |-
00:41:05     assert.js:84
00:41:05       throw new AssertionError(obj);
00:41:05       ^
00:41:05     
00:41:05     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
00:41:05          Called "before" 2 time(s), but expected 1 invocation(s).
00:41:05         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
00:41:05         at Array.forEach (<anonymous>)
00:41:05         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
00:41:05         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
00:41:05         at runCallback (timers.js:661:18)
00:41:05         at tryOnImmediate (timers.js:632:5)
00:41:05         at processImmediate (timers.js:614:5)
00:41:05   ...

    @nodejs/platform-windows

  6. Trott commented on Aug 9, 2018

    @Trott
    Trott
    on Aug 9, 2018
    MemberAuthor

    https://ci.nodejs.org/job/node-test-binary-windows/19063/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=2/console

    03:44:05 not ok 12 async-hooks/test-statwatcher
03:44:05   ---
03:44:05   duration_ms: 0.473
03:44:05   severity: fail
03:44:05   exitcode: 1
03:44:05   stack: |-
03:44:05     assert.js:84
03:44:05       throw new AssertionError(obj);
03:44:05       ^
03:44:05     
03:44:05     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
03:44:05          Called "before" 2 time(s), but expected 1 invocation(s).
03:44:05         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
03:44:05         at Array.forEach (<anonymous>)
03:44:05         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
03:44:05         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
03:44:05         at runCallback (timers.js:661:18)
03:44:05         at tryOnImmediate (timers.js:632:5)
03:44:05         at processImmediate (timers.js:614:5)
03:44:05   ...

  7. Trott commented on Aug 9, 2018

    @Trott
    Trott
    on Aug 9, 2018
    MemberAuthor

    @nodejs/testing

  8. joyeecheung commented on Aug 13, 2018

    @joyeecheung
    joyeecheung
    on Aug 13, 2018
    Member

    Looks like it's not windows-only. Refs: nodejs/reliability#12

    Reason     async-hooks/test-statwatcher
Type       JS_TEST_FAILURE
Failed PR  6 (#21975, #22242, #22274, #22290, #22288, #22293)
Appeared   test-azure_msft-win2016-x64-4, test-joyent-ubuntu1604_sharedlibs_container-x64-1, test-softlayer-ubuntu1604_sharedlibs_container-x64-4, test-digitalocean-ubuntu1604_sharedlibs_container-x64-10
First CI   https://ci.nodejs.org/job/node-test-pull-request/16326/
Last CI    https://ci.nodejs.org/job/node-test-pull-request/16413/
  9. joyeecheung
    added 2 commits that reference this issue on Aug 15, 2018

    test: mark async-hooks/test-statwatcher as flaky

    7dd093e

    test: mark async-hooks/test-statwatcher as flaky

    b87cb5d
  10. targos
    added a commit that references this issue on Aug 19, 2018

    test: mark async-hooks/test-statwatcher as flaky

    d0f236d

  11. Trott commented on Aug 27, 2018

    @Trott
    Trott
    on Aug 27, 2018
    MemberAuthor

    Any ideas of how/where to even start with figuring out what's going on here?

    https://ci.nodejs.org/job/node-test-binary-windows/19555/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=2/console

    03:43:07 not ok 12 async-hooks/test-statwatcher # TODO : Fix flaky test
03:43:07   ---
03:43:07   duration_ms: 0.464
03:43:07   severity: flaky
03:43:07   exitcode: 1
03:43:07   stack: |-
03:43:07     assert.js:84
03:43:07       throw new AssertionError(obj);
03:43:07       ^
03:43:07     
03:43:07     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
03:43:07          Called "before" 2 time(s), but expected 1 invocation(s).
03:43:07         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
03:43:07         at Array.forEach (<anonymous>)
03:43:07         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
03:43:07         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
03:43:07         at runCallback (timers.js:661:18)
03:43:07         at tryOnImmediate (timers.js:632:5)
03:43:07         at processImmediate (timers.js:614:5)
03:43:07   ...
  12. Trott
    closed this as completedon Aug 27, 2018

  13. 45 remaining items

  14. targos
    added a commit that references this issue on Jan 14, 2020

    test: unflake async hooks statwatcher test

    3c16855
  15. BethGriggs
    added a commit that references this issue on Feb 6, 2020

    test: unflake async hooks statwatcher test

    2de25f1

  16. Trott commented on Feb 6, 2020

    @Trott
    Trott
    on Feb 6, 2020
    MemberAuthor

    Looks like this is still an issue.

    https://ci.nodejs.org/job/node-test-binary-windows-js-suites/1618/RUN_SUBSET=0,nodes=win2016-COMPILED_BY-vs2017/console

    22:16:05 not ok 12 async-hooks/test-statwatcher # TODO : Fix flaky test
22:16:05   ---
22:16:05   duration_ms: 0.726
22:16:05   severity: flaky
22:16:05   exitcode: 1
22:16:05   stack: |-
22:16:05     Watcher: w1
22:16:05     current stat data: Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     previous stat data: Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     w1 change to Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     } from Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     Watcher: w2
22:16:05     current stat data: Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     previous stat data: Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     Watcher: w1
22:16:05     current stat data: Stats {
22:16:05       dev: 1074759883,
22:16:05       mode: 33206,
22:16:05       nlink: 1,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 4096,
22:16:05       ino: 3940649674191478,
22:16:05       size: 5,
22:16:05       blocks: 0,
22:16:05       atimeMs: 1580976965321.7537,
22:16:05       mtimeMs: 1580976965321.7537,
22:16:05       ctimeMs: 1580976965321.7537,
22:16:05       birthtimeMs: 1580976965321.7537,
22:16:05       atime: 2020-02-06T08:16:05.322Z,
22:16:05       mtime: 2020-02-06T08:16:05.322Z,
22:16:05       ctime: 2020-02-06T08:16:05.322Z,
22:16:05       birthtime: 2020-02-06T08:16:05.322Z
22:16:05     }
22:16:05     previous stat data: Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     w1 change to Stats {
22:16:05       dev: 1074759883,
22:16:05       mode: 33206,
22:16:05       nlink: 1,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 4096,
22:16:05       ino: 3940649674191478,
22:16:05       size: 5,
22:16:05       blocks: 0,
22:16:05       atimeMs: 1580976965321.7537,
22:16:05       mtimeMs: 1580976965321.7537,
22:16:05       ctimeMs: 1580976965321.7537,
22:16:05       birthtimeMs: 1580976965321.7537,
22:16:05       atime: 2020-02-06T08:16:05.322Z,
22:16:05       mtime: 2020-02-06T08:16:05.322Z,
22:16:05       ctime: 2020-02-06T08:16:05.322Z,
22:16:05       birthtime: 2020-02-06T08:16:05.322Z
22:16:05     } from Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     Watcher: w2
22:16:05     current stat data: Stats {
22:16:05       dev: 1074759883,
22:16:05       mode: 33206,
22:16:05       nlink: 1,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 4096,
22:16:05       ino: 5348024557744759,
22:16:05       size: 5,
22:16:05       blocks: 0,
22:16:05       atimeMs: 1580976965441.7485,
22:16:05       mtimeMs: 1580976965442.7483,
22:16:05       ctimeMs: 1580976965442.7483,
22:16:05       birthtimeMs: 1580976965441.7485,
22:16:05       atime: 2020-02-06T08:16:05.442Z,
22:16:05       mtime: 2020-02-06T08:16:05.443Z,
22:16:05       ctime: 2020-02-06T08:16:05.443Z,
22:16:05       birthtime: 2020-02-06T08:16:05.442Z
22:16:05     }
22:16:05     previous stat data: Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     w2 change to Stats {
22:16:05       dev: 1074759883,
22:16:05       mode: 33206,
22:16:05       nlink: 1,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 4096,
22:16:05       ino: 5348024557744759,
22:16:05       size: 5,
22:16:05       blocks: 0,
22:16:05       atimeMs: 1580976965441.7485,
22:16:05       mtimeMs: 1580976965442.7483,
22:16:05       ctimeMs: 1580976965442.7483,
22:16:05       birthtimeMs: 1580976965441.7485,
22:16:05       atime: 2020-02-06T08:16:05.442Z,
22:16:05       mtime: 2020-02-06T08:16:05.443Z,
22:16:05       ctime: 2020-02-06T08:16:05.443Z,
22:16:05       birthtime: 2020-02-06T08:16:05.442Z
22:16:05     } from Stats {
22:16:05       dev: 0,
22:16:05       mode: 0,
22:16:05       nlink: 0,
22:16:05       uid: 0,
22:16:05       gid: 0,
22:16:05       rdev: 0,
22:16:05       blksize: 0,
22:16:05       ino: 0,
22:16:05       size: 0,
22:16:05       blocks: 0,
22:16:05       atimeMs: 0,
22:16:05       mtimeMs: 0,
22:16:05       ctimeMs: 0,
22:16:05       birthtimeMs: 0,
22:16:05       atime: 1970-01-01T00:00:00.000Z,
22:16:05       mtime: 1970-01-01T00:00:00.000Z,
22:16:05       ctime: 1970-01-01T00:00:00.000Z,
22:16:05       birthtime: 1970-01-01T00:00:00.000Z
22:16:05     }
22:16:05     assert.js:102
22:16:05       throw new AssertionError(obj);
22:16:05       ^
22:16:05     
22:16:05     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
22:16:05          Called "before" 3 time(s), but expected 2 invocation(s).
22:16:05         at checkHook (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\hook-checks.js:51:14)
22:16:05         at Array.forEach (<anonymous>)
22:16:05         at checkInvocations (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\hook-checks.js:28:62)
22:16:05         at Immediate._onImmediate (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\test-statwatcher.js:88:9)
22:16:05         at processImmediate (internal/timers.js:456:21) {
22:16:05       generatedMessage: false,
22:16:05       code: 'ERR_ASSERTION',
22:16:05       actual: 3,
22:16:05       expected: 2,
22:16:05       operator: 'strictEqual'
22:16:05     }
22:16:05   ...

    @lundibundi

  17. Trott
    reopened this on Feb 6, 2020

  18. lundibundi commented on Feb 9, 2020

    @lundibundi
    lundibundi
    on Feb 9, 2020
    Member

    This looks like async-hooks bug now, the statwatcher emits exactly 2 events (based on the log from onchangex which is there till the end of the test) but for some reason, we get another before invocation for the 1st file. I actually tried to reproduce this on Windows 10 but to no avail, it didn't fail at even extreme values of -j --repeat.

  19. Trott commented on Feb 10, 2020

    @Trott
    Trott
    on Feb 10, 2020
    MemberAuthor

    This looks like async-hooks bug now, the statwatcher emits exactly 2 events (based on the log from onchangex which is there till the end of the test) but for some reason, we get another before invocation for the 1st file.

    @nodejs/async_hooks

  20. Trott commented on Feb 10, 2020

    @Trott
    Trott
    on Feb 10, 2020
    MemberAuthor

    https://ci.nodejs.org/job/node-test-binary-windows-js-suites/1705/RUN_SUBSET=0,nodes=win2016-COMPILED_BY-vs2017/console

    test-azure_msft-win2016_vs2017-x64-4

    Details 
    22:19:41 not ok 13 async-hooks/test-statwatcher # TODO : Fix flaky test
22:19:41   ---
22:19:41   duration_ms: 0.562
22:19:41   severity: flaky
22:19:41   exitcode: 1
22:19:41   stack: |-
22:19:41     Watcher: w1
22:19:41     current stat data: Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     previous stat data: Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     w1 change to Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     } from Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     Watcher: w2
22:19:41     current stat data: Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     previous stat data: Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     Watcher: w1
22:19:41     current stat data: Stats {
22:19:41       dev: 1074759883,
22:19:41       mode: 33206,
22:19:41       nlink: 1,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 4096,
22:19:41       ino: 10133099161845984,
22:19:41       size: 5,
22:19:41       blocks: 0,
22:19:41       atimeMs: 1581322781302.6123,
22:19:41       mtimeMs: 1581322781302.6123,
22:19:41       ctimeMs: 1581322781302.6123,
22:19:41       birthtimeMs: 1581322781302.6123,
22:19:41       atime: 2020-02-10T08:19:41.303Z,
22:19:41       mtime: 2020-02-10T08:19:41.303Z,
22:19:41       ctime: 2020-02-10T08:19:41.303Z,
22:19:41       birthtime: 2020-02-10T08:19:41.303Z
22:19:41     }
22:19:41     previous stat data: Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     w1 change to Stats {
22:19:41       dev: 1074759883,
22:19:41       mode: 33206,
22:19:41       nlink: 1,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 4096,
22:19:41       ino: 10133099161845984,
22:19:41       size: 5,
22:19:41       blocks: 0,
22:19:41       atimeMs: 1581322781302.6123,
22:19:41       mtimeMs: 1581322781302.6123,
22:19:41       ctimeMs: 1581322781302.6123,
22:19:41       birthtimeMs: 1581322781302.6123,
22:19:41       atime: 2020-02-10T08:19:41.303Z,
22:19:41       mtime: 2020-02-10T08:19:41.303Z,
22:19:41       ctime: 2020-02-10T08:19:41.303Z,
22:19:41       birthtime: 2020-02-10T08:19:41.303Z
22:19:41     } from Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     Watcher: w2
22:19:41     current stat data: Stats {
22:19:41       dev: 1074759883,
22:19:41       mode: 33206,
22:19:41       nlink: 1,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 4096,
22:19:41       ino: 9570149208424672,
22:19:41       size: 5,
22:19:41       blocks: 0,
22:19:41       atimeMs: 1581322781418.6133,
22:19:41       mtimeMs: 1581322781422.6157,
22:19:41       ctimeMs: 1581322781422.6157,
22:19:41       birthtimeMs: 1581322781418.6133,
22:19:41       atime: 2020-02-10T08:19:41.419Z,
22:19:41       mtime: 2020-02-10T08:19:41.423Z,
22:19:41       ctime: 2020-02-10T08:19:41.423Z,
22:19:41       birthtime: 2020-02-10T08:19:41.419Z
22:19:41     }
22:19:41     previous stat data: Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     w2 change to Stats {
22:19:41       dev: 1074759883,
22:19:41       mode: 33206,
22:19:41       nlink: 1,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 4096,
22:19:41       ino: 9570149208424672,
22:19:41       size: 5,
22:19:41       blocks: 0,
22:19:41       atimeMs: 1581322781418.6133,
22:19:41       mtimeMs: 1581322781422.6157,
22:19:41       ctimeMs: 1581322781422.6157,
22:19:41       birthtimeMs: 1581322781418.6133,
22:19:41       atime: 2020-02-10T08:19:41.419Z,
22:19:41       mtime: 2020-02-10T08:19:41.423Z,
22:19:41       ctime: 2020-02-10T08:19:41.423Z,
22:19:41       birthtime: 2020-02-10T08:19:41.419Z
22:19:41     } from Stats {
22:19:41       dev: 0,
22:19:41       mode: 0,
22:19:41       nlink: 0,
22:19:41       uid: 0,
22:19:41       gid: 0,
22:19:41       rdev: 0,
22:19:41       blksize: 0,
22:19:41       ino: 0,
22:19:41       size: 0,
22:19:41       blocks: 0,
22:19:41       atimeMs: 0,
22:19:41       mtimeMs: 0,
22:19:41       ctimeMs: 0,
22:19:41       birthtimeMs: 0,
22:19:41       atime: 1970-01-01T00:00:00.000Z,
22:19:41       mtime: 1970-01-01T00:00:00.000Z,
22:19:41       ctime: 1970-01-01T00:00:00.000Z,
22:19:41       birthtime: 1970-01-01T00:00:00.000Z
22:19:41     }
22:19:41     assert.js:102
22:19:41       throw new AssertionError(obj);
22:19:41       ^
22:19:41     
22:19:41     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
22:19:41          Called "before" 3 time(s), but expected 2 invocation(s).
22:19:41         at checkHook (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\hook-checks.js:51:14)
22:19:41         at Array.forEach (<anonymous>)
22:19:41         at checkInvocations (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\hook-checks.js:28:62)
22:19:41         at Immediate._onImmediate (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\test-statwatcher.js:88:9)
22:19:41         at processImmediate (internal/timers.js:456:21) {
22:19:41       generatedMessage: false,
22:19:41       code: 'ERR_ASSERTION',
22:19:41       actual: 3,
22:19:41       expected: 2,
22:19:41       operator: 'strictEqual'
22:19:41     }
22:19:41   ...
  21. bzoz
    added a commit that references this issue on Mar 25, 2020

    test: unflake async-hooks/test-statwatcher

    db07b9d
  22. addaleax
    closed this as completedin eb553a4on Mar 29, 2020
  23. addaleax
    added a commit that references this issue on Mar 30, 2020

    test: unflake async-hooks/test-statwatcher

    36c6d22
  24. targos
    added a commit that references this issue on Apr 22, 2020

    test: unflake async-hooks/test-statwatcher

    d9abea5
  25. sjarmak
    added 3 commits that reference this issue on Jul 27, 2026

    test: remove flaky status for test-statwatcher

    f2c573c

    test: unflake async hooks statwatcher test

    ea6a457

    test: unflake async-hooks/test-statwatcher

    eb553a4
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

    async_hooksIssues and PRs related to the async hooks subsystem.flaky-testIssues and PRs involving tests that fail intermittently in CI.linuxIssues and PRs related to the Linux platform.windowsIssues and PRs related to the Windows platform.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions