Investigate flaky async-hooks/test-statwatcher

[Trott]

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

[Trott]

@nodejs/async_hooks @thlorenz

[Trott]

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

[refack]

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

[Trott]

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

[Trott]

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

[Trott]

@nodejs/testing

[joyeecheung]

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/

[Trott]

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