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

Investigate flaky async-hooks/test-statwatcher #21425

Closed
Trott opened this issue Jun 20, 2018 · 35 comments · Fixed by #29392
Closed

Investigate flaky async-hooks/test-statwatcher #21425

Trott opened this issue Jun 20, 2018 · 35 comments · Fixed by #29392
Labels
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. linux Issues and PRs related to the Linux platform. windows Issues and PRs related to the Windows platform.

Comments

@Trott
Copy link
Member

Trott commented 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   ...
@Trott Trott added windows Issues and PRs related to the Windows 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. labels Jun 20, 2018
@Trott
Copy link
Member Author

Trott commented Jun 20, 2018

@nodejs/async_hooks @thlorenz

@cjihrig cjihrig mentioned this issue Jun 22, 2018
Merged
4 tasks
@Trott
Copy link
Member Author

Trott commented Jun 26, 2018

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

@addaleax addaleax mentioned this issue Jul 18, 2018
Closed
2 tasks
@refack refack mentioned this issue Jul 26, 2018
Closed
3 tasks
@refack
Copy link
Contributor

refack commented Jul 26, 2018

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
Copy link
Member Author

Trott commented Jul 30, 2018

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

@shisama shisama mentioned this issue Aug 2, 2018
Closed
2 tasks
@Trott
Copy link
Member Author

Trott commented Aug 9, 2018

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
Copy link
Member Author

Trott commented Aug 9, 2018

@nodejs/testing

@eugeneo eugeneo mentioned this issue Aug 13, 2018
Merged
2 tasks
@joyeecheung
Copy link
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/

@joyeecheung joyeecheung mentioned this issue Aug 14, 2018
Closed
joyeecheung added a commit to joyeecheung/node that referenced this issue Aug 15, 2018
@joyeecheung
test: mark async-hooks/test-statwatcher as flaky
7dd093e 
Refs: nodejs#21425
joyeecheung added a commit that referenced this issue Aug 15, 2018
@joyeecheung
test: mark async-hooks/test-statwatcher as flaky
b87cb5d 
Refs: #21425

PR-URL: #22330
Reviewed-By: Rod Vagg <rod@vagg.org>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
targos pushed a commit that referenced this issue Aug 19, 2018
@joyeecheung @targos
test: mark async-hooks/test-statwatcher as flaky
d0f236d 
Refs: #21425

PR-URL: #22330
Reviewed-By: Rod Vagg <rod@vagg.org>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
@Trott
Copy link
Member Author

Trott commented Aug 27, 2018

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

@Trott Trott closed this as completed Aug 27, 2018
@Trott Trott reopened this Aug 27, 2018
@Trott
Copy link
Member Author

Trott commented Aug 27, 2018

The setTimeout() and setImmediate() nesting looks like it could be a source of unreliability, but I haven't managed to trigger it locally yet. @nodejs/timers

targos pushed a commit that referenced this issue Sep 3, 2018
@joyeecheung @targos
test: mark async-hooks/test-statwatcher as flaky
4a28d38 
Refs: #21425

PR-URL: #22330
Reviewed-By: Rod Vagg <rod@vagg.org>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
@Trott
Copy link
Member Author

Trott commented Sep 23, 2018 •
edited
Loading

Failure on test-azure_msft-win2016-x64-3.

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

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

@Trott
Copy link
Member Author

Trott commented Sep 23, 2018

  • The timer use looks fine. I don't think that's the source of the problem.

  • Not sure where the test was failing on the container shared-lib runs, but I imagine file stuff on containers can get weird. Unless we have output stored somewhere to show that it's failing the same way as the win2016 output in this issue, I think it's best not to assume that it's failing the same way there and to treat this as win2016-only for now.

  • I'll start tracking hosts that this fails on. (Maybe it's Azure-only?)

@Trott
Copy link
Member Author

Trott commented Oct 19, 2018

Host: test-azure_msft-win2016-x64-3

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

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

@Trott
Copy link
Member Author

Trott commented Oct 25, 2018

https://ci.nodejs.org/job/node-test-binary-windows/21022/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=0/console on test-azure_msft-win2016-x64-3

00:56:47 not ok 12 async-hooks/test-statwatcher # TODO : Fix flaky test
00:56:47   ---
00:56:47   duration_ms: 0.524
00:56:47   severity: flaky
00:56:47   exitcode: 1
00:56:47   stack: |-
00:56:47     assert.js:86
00:56:47       throw new AssertionError(obj);
00:56:47       ^
00:56:47     
00:56:47     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
00:56:47          Called "before" 2 time(s), but expected 1 invocation(s).
00:56:47         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
00:56:47         at Array.forEach (<anonymous>)
00:56:47         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
00:56:47         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
00:56:47         at processImmediate (timers.js:632:19)
00:56:47   ...

Kind of hoping the timer queue regression fix will fix this but that seems...unlikely...

@Trott
Copy link
Member Author

Trott commented Oct 26, 2018

https://ci.nodejs.org/job/node-test-binary-windows/21050/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=1/console on test-azure_msft-win2016-x64-2

23:53:58 not ok 12 async-hooks/test-statwatcher # TODO : Fix flaky test
23:53:58   ---
23:53:58   duration_ms: 0.463
23:53:58   severity: flaky
23:53:58   exitcode: 1
23:53:58   stack: |-
23:53:58     assert.js:86
23:53:58       throw new AssertionError(obj);
23:53:58       ^
23:53:58     
23:53:58     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
23:53:58          Called "before" 2 time(s), but expected 1 invocation(s).
23:53:58         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
23:53:58         at Array.forEach (<anonymous>)
23:53:58         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
23:53:58         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
23:53:58         at processImmediate (timers.js:632:19)
23:53:58   ...

@Trott
Copy link
Member Author

Trott commented Nov 21, 2018

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

test-azure_msft-win2016-x64-4

00:52:43 not ok 12 async-hooks/test-statwatcher # TODO : Fix flaky test
00:52:43   ---
00:52:43   duration_ms: 0.478
00:52:43   severity: flaky
00:52:43   exitcode: 1
00:52:43   stack: |-
00:52:43     assert.js:86
00:52:43       throw new AssertionError(obj);
00:52:43       ^
00:52:43     
00:52:43     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
00:52:43          Called "before" 2 time(s), but expected 1 invocation(s).
00:52:43         at checkHook (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:51:14)
00:52:43         at Array.forEach (<anonymous>)
00:52:43         at checkInvocations (c:\workspace\node-test-binary-windows\test\async-hooks\hook-checks.js:28:62)
00:52:43         at Immediate.setImmediate (c:\workspace\node-test-binary-windows\test\async-hooks\test-statwatcher.js:65:9)
00:52:43         at processImmediate (timers.js:632:19)
00:52:43   ...

@Trott Trott mentioned this issue Sep 1, 2019
Merged
2 tasks
@Trott Trott closed this as completed in f2c573c Sep 3, 2019
@Trott
Copy link
Member Author

Trott commented Sep 8, 2019 •
edited
Loading

It's still flaky. I've seen it fail twice on CI in the last week.

@Trott Trott reopened this Sep 8, 2019
@Trott
Copy link
Member Author

Trott commented Sep 8, 2019

https://ci.nodejs.org/job/node-test-commit-linux-containered/14714/nodes=ubuntu1604_sharedlibs_withoutssl_x64/console

test-joyent-ubuntu1604_sharedlibs_container-x64-2

20:59:17 not ok 2463 async-hooks/test-statwatcher
20:59:17   ---
20:59:17   duration_ms: 0.463
20:59:17   severity: fail
20:59:17   exitcode: 1
20:59:17   stack: |-
20:59:17     Watcher: w1
20:59:17     current stat data: Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6826981,
20:59:17       size: 0,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     }
20:59:17     previous stat data: Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6826981,
20:59:17       size: 3,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     }
20:59:17     w1 change Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6826981,
20:59:17       size: 0,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     } Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6826981,
20:59:17       size: 3,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     }
20:59:17     Watcher: w1
20:59:17     current stat data: Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6826981,
20:59:17       size: 5,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157514.2625,
20:59:17       ctimeMs: 1567915157514.2625,
20:59:17       birthtimeMs: 1567915157514.2625,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.514Z,
20:59:17       ctime: 2019-09-08T03:59:17.514Z,
20:59:17       birthtime: 2019-09-08T03:59:17.514Z
20:59:17     }
20:59:17     previous stat data: Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6826981,
20:59:17       size: 0,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     }
20:59:17     Watcher: w2
20:59:17     current stat data: Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6827007,
20:59:17       size: 5,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157626.2598,
20:59:17       ctimeMs: 1567915157626.2598,
20:59:17       birthtimeMs: 1567915157626.2598,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.626Z,
20:59:17       ctime: 2019-09-08T03:59:17.626Z,
20:59:17       birthtime: 2019-09-08T03:59:17.626Z
20:59:17     }
20:59:17     previous stat data: Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6827007,
20:59:17       size: 3,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     }
20:59:17     w2 change Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6827007,
20:59:17       size: 5,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157626.2598,
20:59:17       ctimeMs: 1567915157626.2598,
20:59:17       birthtimeMs: 1567915157626.2598,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.626Z,
20:59:17       ctime: 2019-09-08T03:59:17.626Z,
20:59:17       birthtime: 2019-09-08T03:59:17.626Z
20:59:17     } Stats {
20:59:17       dev: 64784,
20:59:17       mode: 33188,
20:59:17       nlink: 1,
20:59:17       uid: 1001,
20:59:17       gid: 1001,
20:59:17       rdev: 0,
20:59:17       blksize: 4096,
20:59:17       ino: 6827007,
20:59:17       size: 3,
20:59:17       blocks: 8,
20:59:17       atimeMs: 1567915157406.2651,
20:59:17       mtimeMs: 1567915157406.2651,
20:59:17       ctimeMs: 1567915157406.2651,
20:59:17       birthtimeMs: 1567915157406.2651,
20:59:17       atime: 2019-09-08T03:59:17.406Z,
20:59:17       mtime: 2019-09-08T03:59:17.406Z,
20:59:17       ctime: 2019-09-08T03:59:17.406Z,
20:59:17       birthtime: 2019-09-08T03:59:17.406Z
20:59:17     }
20:59:17     assert.js:89
20:59:17       throw new AssertionError(obj);
20:59:17       ^
20:59:17     
20:59:17     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
20:59:17          Called "before" 2 time(s), but expected 1 invocation(s).
20:59:17         at checkHook (/home/iojs/build/workspace/node-test-commit-linux-containered/test/async-hooks/hook-checks.js:51:14)
20:59:17         at Array.forEach (<anonymous>)
20:59:17         at checkInvocations (/home/iojs/build/workspace/node-test-commit-linux-containered/test/async-hooks/hook-checks.js:28:62)
20:59:17         at Immediate._onImmediate (/home/iojs/build/workspace/node-test-commit-linux-containered/test/async-hooks/test-statwatcher.js:77:9)
20:59:17         at processImmediate (internal/timers.js:439:21) {
20:59:17       generatedMessage: false,
20:59:17       code: 'ERR_ASSERTION',
20:59:17       actual: 2,
20:59:17       expected: 1,
20:59:17       operator: 'strictEqual'
20:59:17     }
20:59:17   ...

targos pushed a commit that referenced this issue Sep 20, 2019
@Trott @targos
test: remove flaky status for test-statwatcher
75c559d 
test-statwatcher does not appear to be failing anymore in CI. Remove
"flaky" status for the test.

Closes: #21425

PR-URL: #29392
Fixes: #21425
Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Trivikram Kamat <trivikr.dev@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: David Carlier <devnexen@gmail.com>
@lundibundi lundibundi mentioned this issue Nov 11, 2019
Closed
2 tasks
@gireeshpunathil
Copy link
Member

seen again today:

21:27:41 not ok 26 async-hooks/test-statwatcher
21:27:41   ---
21:27:41   duration_ms: 0.422
21:27:41   severity: fail
21:27:41   exitcode: 1
21:27:41   stack: |-
21:27:41     Watcher: w1
21:27:41     current stat data: Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 27866022694574572,
21:27:41       size: 5,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260942.3242,
21:27:41       ctimeMs: 1574006260942.3242,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.942Z,
21:27:41       ctime: 2019-11-17T15:57:40.942Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     previous stat data: Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 27866022694574572,
21:27:41       size: 3,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260837.3174,
21:27:41       ctimeMs: 1574006260837.3174,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.837Z,
21:27:41       ctime: 2019-11-17T15:57:40.837Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     w1 change Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 27866022694574572,
21:27:41       size: 5,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260942.3242,
21:27:41       ctimeMs: 1574006260942.3242,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.942Z,
21:27:41       ctime: 2019-11-17T15:57:40.942Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     } Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 27866022694574572,
21:27:41       size: 3,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260837.3174,
21:27:41       ctimeMs: 1574006260837.3174,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.837Z,
21:27:41       ctime: 2019-11-17T15:57:40.837Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     Watcher: w1
21:27:41     current stat data: Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 27866022694574572,
21:27:41       size: 5,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260943.3242,
21:27:41       ctimeMs: 1574006260943.3242,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.943Z,
21:27:41       ctime: 2019-11-17T15:57:40.943Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     previous stat data: Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 27866022694574572,
21:27:41       size: 5,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260942.3242,
21:27:41       ctimeMs: 1574006260942.3242,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.942Z,
21:27:41       ctime: 2019-11-17T15:57:40.942Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     Watcher: w2
21:27:41     current stat data: Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 753227037677935100,
21:27:41       size: 5,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006261052.608,
21:27:41       ctimeMs: 1574006261052.608,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:41.053Z,
21:27:41       ctime: 2019-11-17T15:57:41.053Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     previous stat data: Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 753227037677935100,
21:27:41       size: 3,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260838.319,
21:27:41       ctimeMs: 1574006260838.319,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.838Z,
21:27:41       ctime: 2019-11-17T15:57:40.838Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     w2 change Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 753227037677935100,
21:27:41       size: 5,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006261052.608,
21:27:41       ctimeMs: 1574006261052.608,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:41.053Z,
21:27:41       ctime: 2019-11-17T15:57:41.053Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     } Stats {
21:27:41       dev: 748388947,
21:27:41       mode: 33206,
21:27:41       nlink: 1,
21:27:41       uid: 0,
21:27:41       gid: 0,
21:27:41       rdev: 0,
21:27:41       blksize: 4096,
21:27:41       ino: 753227037677935100,
21:27:41       size: 3,
21:27:41       blocks: 0,
21:27:41       atimeMs: 1574006260837.3174,
21:27:41       mtimeMs: 1574006260838.319,
21:27:41       ctimeMs: 1574006260838.319,
21:27:41       birthtimeMs: 1574006260837.3174,
21:27:41       atime: 2019-11-17T15:57:40.837Z,
21:27:41       mtime: 2019-11-17T15:57:40.838Z,
21:27:41       ctime: 2019-11-17T15:57:40.838Z,
21:27:41       birthtime: 2019-11-17T15:57:40.837Z
21:27:41     }
21:27:41     assert.js:93
21:27:41       throw new AssertionError(obj);
21:27:41       ^
21:27:41     
21:27:41     AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
21:27:41          Called "before" 2 time(s), but expected 1 invocation(s).
21:27:41         at checkHook (c:\workspace\node-test-binary-windows-2\test\async-hooks\hook-checks.js:51:14)
21:27:41         at Array.forEach (<anonymous>)
21:27:41         at checkInvocations (c:\workspace\node-test-binary-windows-2\test\async-hooks\hook-checks.js:28:62)
21:27:41         at Immediate._onImmediate (c:\workspace\node-test-binary-windows-2\test\async-hooks\test-statwatcher.js:77:9)
21:27:41         at processImmediate (internal/timers.js:439:21) {
21:27:41       generatedMessage: false,
21:27:41       code: 'ERR_ASSERTION',
21:27:41       actual: 2,
21:27:41       expected: 1,
21:27:41       operator: 'strictEqual'
21:27:41     }

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

@gireeshpunathil
Copy link
Member

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

@joaocgreis
Copy link
Member

joaocgreis commented Dec 8, 2019 •
edited
Loading

I've seen this twice in master runs this week.

Output 
Watcher: w1
current stat data: Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 57420895249200400,
  size: 5,
  blocks: 0,
  atimeMs: 1575706336715.4404,
  mtimeMs: 1575706336843.4375,
  ctimeMs: 1575706336843.4375,
  birthtimeMs: 1575706336715.4404,
  atime: 2019-12-07T08:12:16.715Z,
  mtime: 2019-12-07T08:12:16.843Z,
  ctime: 2019-12-07T08:12:16.843Z,
  birthtime: 2019-12-07T08:12:16.715Z
}
previous stat data: Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 57420895249200400,
  size: 3,
  blocks: 0,
  atimeMs: 1575706336715.4404,
  mtimeMs: 1575706336716.4404,
  ctimeMs: 1575706336716.4404,
  birthtimeMs: 1575706336715.4404,
  atime: 2019-12-07T08:12:16.715Z,
  mtime: 2019-12-07T08:12:16.716Z,
  ctime: 2019-12-07T08:12:16.716Z,
  birthtime: 2019-12-07T08:12:16.715Z
}
w1 change Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 57420895249200400,
  size: 5,
  blocks: 0,
  atimeMs: 1575706336715.4404,
  mtimeMs: 1575706336843.4375,
  ctimeMs: 1575706336843.4375,
  birthtimeMs: 1575706336715.4404,
  atime: 2019-12-07T08:12:16.715Z,
  mtime: 2019-12-07T08:12:16.843Z,
  ctime: 2019-12-07T08:12:16.843Z,
  birthtime: 2019-12-07T08:12:16.715Z
} Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 57420895249200400,
  size: 3,
  blocks: 0,
  atimeMs: 1575706336715.4404,
  mtimeMs: 1575706336716.4404,
  ctimeMs: 1575706336716.4404,
  birthtimeMs: 1575706336715.4404,
  atime: 2019-12-07T08:12:16.715Z,
  mtime: 2019-12-07T08:12:16.716Z,
  ctime: 2019-12-07T08:12:16.716Z,
  birthtime: 2019-12-07T08:12:16.715Z
}
Watcher: w1
current stat data: Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 57420895249200400,
  size: 5,
  blocks: 0,
  atimeMs: 1575706336715.4404,
  mtimeMs: 1575706336848.482,
  ctimeMs: 1575706336848.482,
  birthtimeMs: 1575706336715.4404,
  atime: 2019-12-07T08:12:16.715Z,
  mtime: 2019-12-07T08:12:16.848Z,
  ctime: 2019-12-07T08:12:16.848Z,
  birthtime: 2019-12-07T08:12:16.715Z
}
previous stat data: Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 57420895249200400,
  size: 5,
  blocks: 0,
  atimeMs: 1575706336715.4404,
  mtimeMs: 1575706336843.4375,
  ctimeMs: 1575706336843.4375,
  birthtimeMs: 1575706336715.4404,
  atime: 2019-12-07T08:12:16.715Z,
  mtime: 2019-12-07T08:12:16.843Z,
  ctime: 2019-12-07T08:12:16.843Z,
  birthtime: 2019-12-07T08:12:16.715Z
}
Watcher: w2
current stat data: Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 69805794224469270,
  size: 5,
  blocks: 0,
  atimeMs: 1575706336716.4404,
  mtimeMs: 1575706337020.4365,
  ctimeMs: 1575706337020.4365,
  birthtimeMs: 1575706336716.4404,
  atime: 2019-12-07T08:12:16.716Z,
  mtime: 2019-12-07T08:12:17.020Z,
  ctime: 2019-12-07T08:12:17.020Z,
  birthtime: 2019-12-07T08:12:16.716Z
}
previous stat data: Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 69805794224469270,
  size: 3,
  blocks: 0,
  atimeMs: 1575706336716.4404,
  mtimeMs: 1575706336716.4404,
  ctimeMs: 1575706336716.4404,
  birthtimeMs: 1575706336716.4404,
  atime: 2019-12-07T08:12:16.716Z,
  mtime: 2019-12-07T08:12:16.716Z,
  ctime: 2019-12-07T08:12:16.716Z,
  birthtime: 2019-12-07T08:12:16.716Z
}
w2 change Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 69805794224469270,
  size: 5,
  blocks: 0,
  atimeMs: 1575706336716.4404,
  mtimeMs: 1575706337020.4365,
  ctimeMs: 1575706337020.4365,
  birthtimeMs: 1575706336716.4404,
  atime: 2019-12-07T08:12:16.716Z,
  mtime: 2019-12-07T08:12:17.020Z,
  ctime: 2019-12-07T08:12:17.020Z,
  birthtime: 2019-12-07T08:12:16.716Z
} Stats {
  dev: 1074759883,
  mode: 33206,
  nlink: 1,
  uid: 0,
  gid: 0,
  rdev: 0,
  blksize: 4096,
  ino: 69805794224469270,
  size: 3,
  blocks: 0,
  atimeMs: 1575706336716.4404,
  mtimeMs: 1575706336716.4404,
  ctimeMs: 1575706336716.4404,
  birthtimeMs: 1575706336716.4404,
  atime: 2019-12-07T08:12:16.716Z,
  mtime: 2019-12-07T08:12:16.716Z,
  ctime: 2019-12-07T08:12:16.716Z,
  birthtime: 2019-12-07T08:12:16.716Z
}
assert.js:99
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "watcher1: when unwatched second file":
     Called "before" 2 time(s), but expected 1 invocation(s).
    at checkHook (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\hook-checks.js:51:14)
    at Array.forEach (<anonymous>)
    at checkInvocations (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\hook-checks.js:28:62)
    at Immediate._onImmediate (C:\workspace\node-test-binary-windows-js-suites\node\test\async-hooks\test-statwatcher.js:77:9)
    at processImmediate (internal/timers.js:444:21) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: 2,
  expected: 1,
  operator: 'strictEqual'
}

Ref: https://ci.nodejs.org/job/node-test-binary-windows-js-suites/156/RUN_SUBSET=0,nodes=win2016-COMPILED_BY-vs2017/testReport/junit/(root)/test/async_hooks_test_statwatcher/

On: https://ci.nodejs.org/computer/test-azure_msft-win2016_vs2017-x64-3/

lundibundi added a commit to lundibundi/node that referenced this issue Dec 21, 2019
@lundibundi
test: unflake async hooks statwatcher test
33b8300 
Under high load 2 types of issues arise with this test.
* filesystem calls gets queued even when the 'sync' is used which leads
  to async_hooks being called with the events of tmpdir clean or
  initial file write after clean.
  This is solved by counting all 'change' calls while making sure there
  is no dependency of StatWatcher's on one another and the expected
  changes are waited for.

* some events are getting lost with the current
  clean->write->write_and_watch strategy. Specifically I observed the
  file size going from 0 to 5 entirely skipping 3 even though the write
  call was there (this happened reliably on -j128).
  So I've changed the strategy to avoid additional write considering
  this still tests the hooks correctly.
  This may indicate some sort of bug in async_hooks though I'm not sure.

Closes: nodejs#21425
@Trott Trott closed this as completed in ea6a457 Dec 22, 2019
BridgeAR pushed a commit that referenced this issue Jan 3, 2020
@lundibundi @BridgeAR
test: unflake async hooks statwatcher test
3c9e435 
Under high load 2 types of issues arise with this test.
* filesystem calls gets queued even when the 'sync' is used which leads
  to async_hooks being called with the events of tmpdir clean or
  initial file write after clean.
  This is solved by counting all 'change' calls while making sure there
  is no dependency of StatWatcher's on one another and the expected
  changes are waited for.

* some events are getting lost with the current
  clean->write->write_and_watch strategy. Specifically I observed the
  file size going from 0 to 5 entirely skipping 3 even though the write
  call was there (this happened reliably on -j128).
  So I've changed the strategy to avoid additional write considering
  this still tests the hooks correctly.
  This may indicate some sort of bug in async_hooks though I'm not sure.

Closes: #21425

PR-URL: #30362
Fixes: #21425
Reviewed-By: Stephen Belanger <admin@stephenbelanger.com>
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
Reviewed-By: Vladimir de Turckheim <vlad2t@hotmail.com>
targos pushed a commit that referenced this issue Jan 14, 2020
@lundibundi @targos
test: unflake async hooks statwatcher test
3c16855 
Under high load 2 types of issues arise with this test.
* filesystem calls gets queued even when the 'sync' is used which leads
  to async_hooks being called with the events of tmpdir clean or
  initial file write after clean.
  This is solved by counting all 'change' calls while making sure there
  is no dependency of StatWatcher's on one another and the expected
  changes are waited for.

* some events are getting lost with the current
  clean->write->write_and_watch strategy. Specifically I observed the
  file size going from 0 to 5 entirely skipping 3 even though the write
  call was there (this happened reliably on -j128).
  So I've changed the strategy to avoid additional write considering
  this still tests the hooks correctly.
  This may indicate some sort of bug in async_hooks though I'm not sure.

Closes: #21425

PR-URL: #30362
Fixes: #21425
Reviewed-By: Stephen Belanger <admin@stephenbelanger.com>
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
Reviewed-By: Vladimir de Turckheim <vlad2t@hotmail.com>
BethGriggs pushed a commit that referenced this issue Feb 6, 2020
@lundibundi @BethGriggs
test: unflake async hooks statwatcher test
2de25f1 
Under high load 2 types of issues arise with this test.
* filesystem calls gets queued even when the 'sync' is used which leads
  to async_hooks being called with the events of tmpdir clean or
  initial file write after clean.
  This is solved by counting all 'change' calls while making sure there
  is no dependency of StatWatcher's on one another and the expected
  changes are waited for.

* some events are getting lost with the current
  clean->write->write_and_watch strategy. Specifically I observed the
  file size going from 0 to 5 entirely skipping 3 even though the write
  call was there (this happened reliably on -j128).
  So I've changed the strategy to avoid additional write considering
  this still tests the hooks correctly.
  This may indicate some sort of bug in async_hooks though I'm not sure.

Closes: #21425

PR-URL: #30362
Fixes: #21425
Reviewed-By: Stephen Belanger <admin@stephenbelanger.com>
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
Reviewed-By: Vladimir de Turckheim <vlad2t@hotmail.com>
@Trott
Copy link
Member Author

Trott commented Feb 6, 2020

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

@Trott Trott reopened this Feb 6, 2020
@lundibundi
Copy link
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.

@Trott
Copy link
Member Author

Trott commented Feb 10, 2020

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

@Trott
Copy link
Member Author

Trott commented Feb 10, 2020

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

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

bzoz added a commit to JaneaSystems/node that referenced this issue Mar 25, 2020
@bzoz
test: unflake async-hooks/test-statwatcher
db07b9d 
On Windows 2016 under high load further change events can be emitted
after writing the 5 bytes is reported. Updating the mtime of the file
can be reported as a separate change. This will increase the "before"
count, but not the "w1HookCount" since we removed the listener.

This makes the test keep the listeners until the end of the test.

Fixes: nodejs#21425
@bzoz bzoz mentioned this issue Mar 25, 2020
Closed
2 tasks
addaleax pushed a commit that referenced this issue Mar 30, 2020
@bzoz @addaleax
test: unflake async-hooks/test-statwatcher
36c6d22 
On Windows 2016 under high load further change events can be emitted
after writing the 5 bytes is reported. Updating the mtime of the file
can be reported as a separate change. This will increase the "before"
count, but not the "w1HookCount" since we removed the listener.

This makes the test keep the listeners until the end of the test.

Fixes: #21425

PR-URL: #32484
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
targos pushed a commit that referenced this issue Apr 22, 2020
@bzoz @targos
test: unflake async-hooks/test-statwatcher
d9abea5 
On Windows 2016 under high load further change events can be emitted
after writing the 5 bytes is reported. Updating the mtime of the file
can be reported as a separate change. This will increase the "before"
count, but not the "w1HookCount" since we removed the listener.

This makes the test keep the listeners until the end of the test.

Fixes: #21425

PR-URL: #32484
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: James M Snell <jasnell@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
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. linux Issues and PRs related to the Linux platform. windows Issues and PRs related to the Windows platform.
Projects
None yet
Milestone
No milestone
8 participants
@sam-github @refack @joaocgreis @Trott @addaleax @joyeecheung @gireeshpunathil @lundibundi