win64-cross CI timeout: `wine: chdir to /tmp/wine-JFrcnM/server-30-e86edd : No such file or directory`; `01e0:err:module:relocate_ntdll ntdll could not be mapped at preferred address (0x320000), expect trouble` #30969

https://cirrus-ci.com/task/6567392808009728?logs=ci#L2620

...
127/137 Test [#131](/bitcoin-bitcoin/131/): spend_tests ..........................   Passed    6.37 sec
        Start 137: db_tests
128/137 Test [#135](/bitcoin-bitcoin/135/): walletdb_tests .......................   Passed    3.02 sec
129/137 Test [#137](/bitcoin-bitcoin/137/): db_tests .............................   Passed    2.91 sec
130/137 Test [#136](/bitcoin-bitcoin/136/): walletload_tests .....................   Passed    5.63 sec
131/137 Test [#133](/bitcoin-bitcoin/133/): wallet_tests .........................   Passed   14.11 sec
132/137 Test [#123](/bitcoin-bitcoin/123/): coinselector_tests ...................   Passed   30.10 sec
133/137 Test   [#5](/bitcoin-bitcoin/5/): noverify_tests .......................   Passed  152.20 sec
134/137 Test   [#6](/bitcoin-bitcoin/6/): tests ................................   Passed  222.76 sec
135/137 Test   [#3](/bitcoin-bitcoin/3/): univalue_test ........................   Passed  224.52 sec
136/137 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  454.44 sec
Timed out!

This is odd, because normally it should pass in less than 15 minutes:https://cirrus-ci.com/task/4920689327603712

Looks like allocator_tests never finished.

https://cirrus-ci.com/task/4822998216081408?logs=ci#L2609

So I guess it is not allocator tests.

Maybe a wine issue?

I opened #30981 to enable cirrus log timestamps. They may help in shedding some more light on where these timeout jobs are spending time, although in this case it seems to be a deeper bug...

It is just 2 hours of nothing (no logs, etc):

[10:48:14.556] 135/136 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  550.41 sec
[12:17:58.568] 
[12:17:58.568] Timed out!

https://cirrus-ci.com/task/5511579989442560?logs=ci#L2605

We might consider the --timeout and --repeat after-timeout flags for the ctest command.

--repeat

Any kind of automated repeat would be horrible in the CI. Some failures (often UB) are real and intermittent. Silently ignoring them makes a good chunk of the CI pointless.

timeout

Yeah, sounds great. In most cases it probably doesn't hurt for the unit tests to follow what the functional tests are doing.

It is just 2 hours of nothing (no logs, etc):

This is also odd, because the ctest default global timeout, should be 25 minutes: https://github.com/Kitware/CMake/blob/master/Tests/CMakeLists.txt#L331:

Use 1500 or CTEST_TEST_TIMEOUT for long test timeout value, whichever is greater.

As far as I'm aware, we aren't setting CTEST_TEST_TIMEOUT, or increasing this limit in any way, so any stuck test should already be getting killed after that amount of time?

Maybe the documentation is not correct, or ctest is buggy.

Cross compiling master for Windows, and running ctest --test-dir build --extra-verbose, I see:

ctest --test-dir build --extra-verbose
Internal ctest changing into directory: /root/ci_scratch/build
UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
Test project /root/ci_scratch/build
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 1
        Start   1: util_test_runner

1: Test command: /usr/bin/cmake "-E" "env" "BITCOINUTIL=/root/ci_scratch/build/src/bitcoin-util.exe" "BITCOINTX=/root/ci_scratch/build/src/bitcoin-tx.exe" "/usr/bin/python3" "/root/ci_scratch/build/test/util/test_runner.py"
1: Working Directory: /root/ci_scratch/build
1: Test timeout computed to be: 10000000

So timeout after about 3.8 months?

If I run again with ctest --test-dir build --extra-verbose --timeout 3, I get:

ctest --test-dir build --extra-verbose --timeout 3
Internal ctest changing into directory: /root/ci_scratch/build
UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
Test project /root/ci_scratch/build
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 1
        Start   1: util_test_runner

1: Test command: /usr/bin/cmake "-E" "env" "BITCOINUTIL=/root/ci_scratch/build/src/bitcoin-util.exe" "BITCOINTX=/root/ci_scratch/build/src/bitcoin-tx.exe" "/usr/bin/python3" "/root/ci_scratch/build/test/util/test_runner.py"
1: Working Directory: /root/ci_scratch/build
1: Test timeout computed to be: 3

Guess I'm now seeing something similar locally when running the CI (fc642c33ef28829eda0119a0fe39fd9bc4b84051). Can't see why univalue_object_test would take three and a half minutes to run (included other known long-running tests for reference):

Test project /ci_container_base/ci/scratch/build-x86_64-w64-mingw32
        Start   1: util_test_runner

  3/136 Test   [#5](/bitcoin-bitcoin/5/): noverify_tests .......................   Passed   86.08 sec
  5/136 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  100.97 sec
 11/136 Test   [#8](/bitcoin-bitcoin/8/): bench_sanity_check_high_priority .....   Passed   15.59 sec
 58/136 Test   [#6](/bitcoin-bitcoin/6/): tests ................................   Passed  147.61 sec
135/136 Test [#136](/bitcoin-bitcoin/136/): db_tests .............................   Passed    1.69 sec
136/136 Test   [#4](/bitcoin-bitcoin/4/): univalue_object_test .................   Passed  216.27 sec

100% tests passed, 0 tests failed out of 136

Total Test time (real) = 216.28 sec

https://cirrus-ci.com/task/5934269598531584?logs=ci#L2683:

[14:05:20.035] 131/136 Test [#132](/bitcoin-bitcoin/132/): wallet_tests .........................   Passed   16.54 sec
[14:05:27.163] 132/136 Test [#122](/bitcoin-bitcoin/122/): coinselector_tests ...................   Passed   35.31 sec
[14:07:02.612] 133/136 Test   [#6](/bitcoin-bitcoin/6/): tests ................................   Passed  262.37 sec
[14:07:04.392] 134/136 Test   [#9](/bitcoin-bitcoin/9/): addrman_tests ........................   Passed  264.14 sec
[14:10:59.874] 135/136 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  499.64 sec
[15:37:57.567] 
[15:37:57.567] Timed out!

Hitting the 20m --timeout https://cirrus-ci.com/task/5886749702881280:

[17:40:38.816] 129/136 Test [#135](/bitcoin-bitcoin/135/): walletload_tests .....................   Passed    4.68 sec
[17:40:42.991] 130/136 Test [#132](/bitcoin-bitcoin/132/): wallet_tests .........................   Passed   11.89 sec
[17:40:47.154] 131/136 Test [#122](/bitcoin-bitcoin/122/): coinselector_tests ...................   Passed   23.22 sec
[17:40:54.153] 132/136 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  119.52 sec
[17:41:12.100] 133/136 Test   [#5](/bitcoin-bitcoin/5/): noverify_tests .......................   Passed  137.46 sec
[17:43:01.835] 134/136 Test  [#10](/bitcoin-bitcoin/10/): allocator_tests ......................   Passed  247.18 sec
[17:43:01.843] 135/136 Test   [#6](/bitcoin-bitcoin/6/): tests ................................   Passed  247.20 sec
[17:58:54.731] 136/136 Test   [#9](/bitcoin-bitcoin/9/): addrman_tests ........................***Timeout 1200.08 sec
[17:58:54.732] wine: created the configuration directory '/root/.wine'
[17:58:54.732] wine: chdir to /tmp/wine-JFrcnM/server-30-e86edd : No such file or directory
[17:58:54.732] 01e0:err:module:relocate_ntdll ntdll could not be mapped at preferred address (0x320000), expect trouble
[17:58:54.732] Running 23 test cases...
[17:58:54.732] Test cases order is shuffled using seed: 1728322709

The addrman_tests normally take 14 seconds (https://cirrus-ci.com/task/5931376359243776?logs=ci#L2350), so I guess this issue is a duplicate of #23357, just that ctest turned the fail into a timeout.

No idea how to fix this. I'd say to just replace the Wine tests finally: https://github.com/bitcoin/bitcoin/issues/31071

Let's move discussion to #31071