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