Investigate flaky test-watch-mode (no. 3)

[tniessen]

Test

test-watch-mode

Platform

Linux x64, FreeBSD

Console output

13:17:49 not ok 3811 sequential/test-watch-mode
13:17:55   ---
13:17:55   duration_ms: 5.291
13:17:55   severity: fail
13:17:55   exitcode: 1
13:17:55   stack: |-
13:17:55     TAP version 13
13:17:55     # Subtest: watch mode
13:17:55         # Subtest: should watch changes to a file - event loop ended
13:17:55         ok 1 - should watch changes to a file - event loop ended
13:17:55           ---
13:17:55           duration_ms: 2739.793821
13:17:55           ...
13:17:55         # Subtest: should watch changes to a failing file
13:17:55         ok 2 - should watch changes to a failing file
13:17:55           ---
13:17:55           duration_ms: 2477.028169
13:17:55           ...
13:17:55         # Subtest: should not watch when running an non-existing file
13:17:55         ok 3 - should not watch when running an non-existing file
13:17:55           ---
13:17:55           duration_ms: 2285.642733
13:17:55           ...
13:17:55         # Subtest: should watch when running an non-existing file - when specified under --watch-path
13:17:55         ok 4 - should watch when running an non-existing file - when specified under --watch-path # SKIP
13:17:55           ---
13:17:55           duration_ms: 209.591623
13:17:55           ...
13:17:55         # Subtest: should watch changes to a file - event loop blocked
13:17:55         not ok 5 - should watch changes to a file - event loop blocked
13:17:55           ---
13:17:55           duration_ms: 2870.03467
13:17:55           failureType: 'testCodeFailure'
13:17:55           error: |-
13:17:55             Expected values to be strictly deep-equal:
13:17:55             + actual - expected
13:17:55             
13:17:55               [
13:17:55             +   'running',
13:17:55             +   "Restarting '/home/iojs/build/workspace/node-test-commit-linux-containered/test/fixtures/watch-mode/event_loop_blocked.js'"
13:17:55             -   "Restarting '/home/iojs/build/workspace/node-test-commit-linux-containered/test/fixtures/watch-mode/event_loop_blocked.js'",
13:17:55             -   'running'
13:17:55               ]
13:17:55           code: 'ERR_ASSERTION'
13:17:55           stack: |-
13:17:55             assertRestartedCorrectly (file:///home/iojs/build/workspace/node-test-commit-linux-containered/test/sequential/test-watch-mode.mjs:74:10)
13:17:55             Object.<anonymous> (file:///home/iojs/build/workspace/node-test-commit-linux-containered/test/sequential/test-watch-mode.mjs:141:5)
13:17:55             process.processTicksAndRejections (node:internal/process/task_queues:95:5)
13:17:55             async ItTest.run (node:internal/test_runner/test:512:9)
13:17:55             async Promise.all (index 4)
13:17:55             async Suite.run (node:internal/test_runner/test:739:7)
13:17:55           ...
13:17:55         # Subtest: should watch changes to dependencies - cjs
13:17:55         ok 6 - should watch changes to dependencies - cjs
13:17:55           ---
13:17:55           duration_ms: 2782.278082
13:17:55           ...
13:17:55         # Subtest: should watch changes to dependencies - esm
13:17:55         ok 7 - should watch changes to dependencies - esm
13:17:55           ---
13:17:55           duration_ms: 2598.258289
13:17:55           ...
13:17:55         # Subtest: should restart multiple times
13:17:55         ok 8 - should restart multiple times
13:17:55           ---
13:17:55           duration_ms: 4515.95009
13:17:55           ...
13:17:55         # Subtest: should pass arguments to file
13:17:55         ok 9 - should pass arguments to file
13:17:55           ---
13:17:55           duration_ms: 2784.227409
13:17:55           ...
13:17:55         # Subtest: should not load --require modules in main process
13:17:55         ok 10 - should not load --require modules in main process
13:17:55           ---
13:17:55           duration_ms: 2822.566444
13:17:55           ...
13:17:55         # Subtest: should not load --import modules in main process
13:17:55         ok 11 - should not load --import modules in main process
13:17:55           ---
13:17:55           duration_ms: 2968.502896
13:17:55           ...
13:17:55         1..11
13:17:55     not ok 1 - watch mode
13:17:55       ---
13:17:55       duration_ms: 4638.010352
13:17:55       failureType: 'subtestsFailed'
13:17:55       error: '1 subtest failed'
13:17:55       code: 'ERR_TEST_FAILURE'
13:17:55       ...
13:17:55     1..1
13:17:55     # tests 1
13:17:55     # pass 0
13:17:55     # fail 1
13:17:55     # cancelled 0
13:17:55     # skipped 0
13:17:55     # todo 0
13:17:55     # duration_ms 4649.416376
13:17:55   ...

Build links

• https://ci.nodejs.org/job/node-test-commit-linux-containered/34022/nodes=ubuntu1804_sharedlibs_shared_x64/console
• https://ci.nodejs.org/job/node-test-commit-freebsd/46261/nodes=freebsd12-x64/console
• https://ci.nodejs.org/job/node-test-commit-freebsd/46216/nodes=freebsd12-x64/console

Additional information

Refs: #44655
Refs: #44735
Refs: #44805

[tniessen]

Similar output:

16:12:03 not ok 3793 sequential/test-watch-mode
16:12:06   ---
16:12:06   duration_ms: 3.677
16:12:06   severity: fail
16:12:06   exitcode: 1
16:12:06   stack: |-
16:12:06     TAP version 13
16:12:06     # Subtest: watch mode
16:12:06         # Subtest: should watch changes to a file - event loop ended
16:12:06         ok 1 - should watch changes to a file - event loop ended
16:12:06           ---
16:12:06           duration_ms: 1657.422205
16:12:06           ...
16:12:06         # Subtest: should watch changes to a failing file
16:12:06         ok 2 - should watch changes to a failing file
16:12:06           ---
16:12:06           duration_ms: 2144.675239
16:12:06           ...
16:12:06         # Subtest: should not watch when running an non-existing file
16:12:06         ok 3 - should not watch when running an non-existing file
16:12:06           ---
16:12:06           duration_ms: 848.075766
16:12:06           ...
16:12:06         # Subtest: should watch when running an non-existing file - when specified under --watch-path
16:12:06         ok 4 - should watch when running an non-existing file - when specified under --watch-path # SKIP
16:12:06           ---
16:12:06           duration_ms: 281.828198
16:12:06           ...
16:12:06         # Subtest: should watch changes to a file - event loop blocked
16:12:06         ok 5 - should watch changes to a file - event loop blocked
16:12:06           ---
16:12:06           duration_ms: 1094.820609
16:12:06           ...
16:12:06         # Subtest: should watch changes to dependencies - cjs
16:12:06         ok 6 - should watch changes to dependencies - cjs
16:12:06           ---
16:12:06           duration_ms: 2049.295256
16:12:06           ...
16:12:06         # Subtest: should watch changes to dependencies - esm
16:12:06         ok 7 - should watch changes to dependencies - esm
16:12:06           ---
16:12:06           duration_ms: 2216.116407
16:12:06           ...
16:12:06         # Subtest: should restart multiple times
16:12:06         ok 8 - should restart multiple times
16:12:06           ---
16:12:06           duration_ms: 3098.411375
16:12:06           ...
16:12:06         # Subtest: should pass arguments to file
16:12:06         ok 9 - should pass arguments to file
16:12:06           ---
16:12:06           duration_ms: 1908.309201
16:12:06           ...
16:12:06         # Subtest: should not load --require modules in main process
16:12:06         ok 10 - should not load --require modules in main process
16:12:06           ---
16:12:06           duration_ms: 1360.515837
16:12:06           ...
16:12:06         # Subtest: should not load --import modules in main process
16:12:06         not ok 11 - should not load --import modules in main process
16:12:06           ---
16:12:06           duration_ms: 2044.114142
16:12:06           failureType: 'testCodeFailure'
16:12:06           error: |-
16:12:06             Expected values to be strictly deep-equal:
16:12:06             + actual - expected
16:12:06             
16:12:06               [
16:12:06             +   "Completed running '/usr/home/iojs/node-tmp/.tmp.3792/3.js'",
16:12:06             +   "Restarting '/usr/home/iojs/node-tmp/.tmp.3792/3.js'"
16:12:06             -   "Restarting '/usr/home/iojs/node-tmp/.tmp.3792/3.js'",
16:12:06             -   "Completed running '/usr/home/iojs/node-tmp/.tmp.3792/3.js'"
16:12:06               ]
16:12:06           code: 'ERR_ASSERTION'
16:12:06           stack: |-
16:12:06             assertRestartedCorrectly (file:///usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/sequential/test-watch-mode.mjs:74:10)
16:12:06             Object.<anonymous> (file:///usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd12-x64/test/sequential/test-watch-mode.mjs:218:5)
16:12:06             process.processTicksAndRejections (node:internal/process/task_queues:95:5)
16:12:06             async ItTest.run (node:internal/test_runner/test:512:9)
16:12:06             async Promise.all (index 10)
16:12:06             async Suite.run (node:internal/test_runner/test:739:7)
16:12:06           ...
16:12:06         1..11
16:12:06     not ok 1 - watch mode
16:12:06       ---
16:12:06       duration_ms: 3336.446593
16:12:06       failureType: 'subtestsFailed'
16:12:06       error: '1 subtest failed'
16:12:06       code: 'ERR_TEST_FAILURE'
16:12:06       ...
16:12:06     1..1
16:12:06     # tests 1
16:12:06     # pass 0
16:12:06     # fail 1
16:12:06     # cancelled 0
16:12:06     # skipped 0
16:12:06     # todo 0
16:12:06     # duration_ms 3344.389888
16:12:06   ...

@MoLow Looks like the order within some arrays is non-deterministic. Not sure if that's a bug in the implementation or in the test.

[MoLow]

On vacation, will have to wait unless someone else wants to give it a look

[pbo-linaro]

This issue was observed on Windows on Arm platform too.

@tniessen @MoLow @richardlau Would you accept to mark those tests as flaky, waiting for a proper fix?

[kapouer]

That test is failing in a variety of ways on our debian builds too (https://buildd.debian.org/status/package.php?p=nodejs&suite=experimental)

[pbo-linaro]

Created a PR to mark those test-watch-mode as flaky, so it can unlock the current situation.

[kapouer]

IMO they're more than flaky, several times they just hang for a long time.

[pbo-linaro]

Is there a timeout of stuff like this we can set for nodejs tests? Or deletion is the only alternative?

[kapouer]

In theory there is already a timeout for tests, but in the case of that test it didn't work (as usual, take what I say with precautions because it's with the debian build of nodejs) and the whole test suite just hang.

[pbo-linaro]

@richardlau @MoLow Should we delete those tests for now, as they seem to create some difficult problems? I know it's not ideal, but hanging a testsuite and report random failures is really a huge difficulty.

[MoLow]

the timeouts happen in the test-watch-mode-inspect tests, and flakyness in test-watch-mode,
I am planning to take a deeper look but I am with a temporary computer for a while - I think for the time it is ok to mark as flaky without deleting