test: is sequential/test-fs-watch flaky on macOS

[refack]

• Version: master
• Platform: macOS
• Subsystem: test

https://ci.nodejs.org/job/node-test-commit-osx/9629/nodes=osx1010/tapResults/

1393	sequential/test-fs-watch	
duration_ms	
60.74
severity	
fail
stack	
timeout

/cc @nodejs/platform-macos

[aashil]

I would like to work on this issue.

[refack]

@aashil Go for it 🥇

[aashil]

@refack I tried running this test using ./node test/sequential/test-fs-watch.js and I got nothing. I assume the test ran with no errors?

[aqrln]

@aashil it did. You can try something like python tools/test.py --mode=release --repeat=10000 sequential/test-fs-watch and see if it starts failing after a couple of minutes of running. However, a better strategy might be to examine its source code and try to find out the reason analytically and not empirically.

[refack]

Since it was a timeout issue that happens only occasionally, it might be hard to reproduce empirically...

[Trott]

I can replicate the issue reasonably reliably by doing the following:

• copy the test into test/parallel
• run with tools/test.py --mode=release --repeat=64 -j 16 test/parallel/test-fs-watch.js

When I run it that way, it runs successfully a lot but also times out a lot.

I have not investigated further at this time, but this all suggests that the test is flaky when the system is under load and/or when the test is competing with other processes for specific resources.

[aashil]

I was able to replicate the issue after suggestions from @aqrln and @Trott I will look into this in more detail.

[aashil]

@Trott @refack @aqrln Shouldn't the behavior of the test be the same when running via tools/test.py and running via a script which runs ./node test/sequential/test-fs-watch.js given number of times? With the latter approach I have console.log statements set up at different points which would help me identify which command in the test times out but, the tests never time out, which makes me think if the timeout is specific to calling via tools/test.py Do you have an alternative or a better approach to debug the test?

[Trott]

@Trott @refack @aqrln Shouldn't the behavior of the test be the same when running via tools/test.py and running via a script which runs ./node test/sequential/test-fs-watch.js given number of times?

@aashil No. tools/test.py --mode=release --repeat=64 -j 16 test/parallel/test-fs-watch.js will run those tests in parallel. ./node test/sequential/test-fs-watch.js a given number of times will run them sequentially.

[aqrln]

@aashil besides that, right, it is tools/test.py watching that a test does not exceed the maximal timeframe. However, you can see if it would fail because of that even without the test harness, because if a test fails with timeout, it usually means that it has hung.

[MylesBorins]

looks like we might have an AIX failure for this on v6.x

https://ci.nodejs.org/job/node-test-commit-aix/5888/nodes=aix61-ppc64/console

not ok 1317 sequential/test-fs-watch
  ---
  duration_ms: 0.430
  severity: fail
  stack: |-
    
    assert.js:81
      throw new assert.AssertionError({
      ^
    AssertionError: Got unwanted exception..
        at _throws (assert.js:356:5)
        at Function.assert.doesNotThrow (assert.js:374:3)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-fs-watch.js:35:8)
        at Module._compile (module.js:570:32)
        at Object.Module._extensions..js (module.js:579:10)
        at Module.load (module.js:487:32)
        at tryModuleLoad (module.js:446:12)
        at Function.Module._load (module.js:438:3)
        at Module.runMain (module.js:604:10)
        at run (bootstrap_node.js:389:7)

[gibfahn]

looks like we might have an AIX failure for this on v6.x

For posterity this turned out to be unrelated (see #13070)

[refack]

Stress macOS: https://ci.nodejs.org/job/node-stress-single-test/1312/nodes=osx1010/
Stress AIX: https://ci.nodejs.org/job/node-stress-single-test/1311/nodes=aix61-ppc64/

[refack]

Stress passed (when run as parallel with refack@63ef897):

macOS:

+ python tools/test.py -p tap --mode=release -j 16 sequential/test-fs-watch
TAP version 13
1..1
ok 1 sequential/test-fs-watch
  ---
  duration_ms: 0.134
  ...
+ OK=99
+ echo '99   OK: 99   NOT OK: 0   TOTAL: 100'
99   OK: 99   NOT OK: 0   TOTAL: 100
+ for i in '`seq $RUN_TIMES`'
+ python tools/test.py -p tap --mode=release -j 16 sequential/test-fs-watch
TAP version 13
1..1
ok 1 sequential/test-fs-watch
  ---
  duration_ms: 0.399
  ...
+ OK=100
+ echo '100   OK: 100   NOT OK: 0   TOTAL: 100'
100   OK: 100   NOT OK: 0   TOTAL: 100
+ '[' 0 '!=' 0 ']'
Notifying upstream projects of job completion
Finished: SUCCESS

AIX:

+ python tools/test.py -p tap --mode=release -j 16 sequential/test-fs-watch
TAP version 13
1..1
ok 1 sequential/test-fs-watch
  ---
  duration_ms: 0.423
  ...
+ OK=99
+ echo '99   OK: 99   NOT OK: 0   TOTAL: 100'
99   OK: 99   NOT OK: 0   TOTAL: 100
+ for i in '`seq $RUN_TIMES`'
+ python tools/test.py -p tap --mode=release -j 16 sequential/test-fs-watch
TAP version 13
1..1
ok 1 sequential/test-fs-watch
  ---
  duration_ms: 0.489
  ...
+ OK=100
+ echo '100   OK: 100   NOT OK: 0   TOTAL: 100'
100   OK: 100   NOT OK: 0   TOTAL: 100
+ '[' 0 '!=' 0 ']'
Notifying upstream projects of job completion
Finished: SUCCESS

Closing for now