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`

maflcko commented at 1:57 pm on September 25, 2024: member

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

 0...
 1127/137 Test [#131](/bitcoin-bitcoin/131/): spend_tests ..........................   Passed    6.37 sec
 2        Start 137: db_tests
 3128/137 Test [#135](/bitcoin-bitcoin/135/): walletdb_tests .......................   Passed    3.02 sec
 4129/137 Test [#137](/bitcoin-bitcoin/137/): db_tests .............................   Passed    2.91 sec
 5130/137 Test [#136](/bitcoin-bitcoin/136/): walletload_tests .....................   Passed    5.63 sec
 6131/137 Test [#133](/bitcoin-bitcoin/133/): wallet_tests .........................   Passed   14.11 sec
 7132/137 Test [#123](/bitcoin-bitcoin/123/): coinselector_tests ...................   Passed   30.10 sec
 8133/137 Test   [#5](/bitcoin-bitcoin/5/): noverify_tests .......................   Passed  152.20 sec
 9134/137 Test   [#6](/bitcoin-bitcoin/6/): tests ................................   Passed  222.76 sec
10135/137 Test   [#3](/bitcoin-bitcoin/3/): univalue_test ........................   Passed  224.52 sec
11136/137 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  454.44 sec
12Timed out!

maflcko added the label CI failed on Sep 25, 2024

maflcko commented at 2:38 pm on September 25, 2024: member

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.

maflcko renamed this:
~~win64-cross CI timeout after 2h~~
win64-cross CI timeout after 2h in allocator_tests
on Sep 25, 2024

maflcko commented at 2:12 pm on September 26, 2024: member

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

So I guess it is not allocator tests.

Maybe a wine issue?

maflcko renamed this:
~~win64-cross CI timeout after 2h in allocator_tests~~
win64-cross CI timeout after 2h
on Sep 26, 2024

willcl-ark commented at 2:31 pm on September 26, 2024: member

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…

fanquake referenced this in commit 36ad9516db on Sep 26, 2024

maflcko commented at 12:39 pm on September 27, 2024: member

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

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

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

hebasto commented at 12:56 pm on September 27, 2024: member

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

maflcko commented at 1:17 pm on September 27, 2024: member

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

fanquake commented at 2:36 pm on September 27, 2024: member

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?

fanquake commented at 3:08 pm on September 27, 2024: member

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:

 0ctest --test-dir build --extra-verbose
 1Internal ctest changing into directory: /root/ci_scratch/build
 2UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
 3UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
 4Test project /root/ci_scratch/build
 5Constructing a list of tests
 6Done constructing a list of tests
 7Updating test list for fixtures
 8Added 0 tests to meet fixture requirements
 9Checking test dependency graph...
10Checking test dependency graph end
11test 1
12        Start   1: util_test_runner
13
141: 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"
151: Working Directory: /root/ci_scratch/build
161: 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:

 0ctest --test-dir build --extra-verbose --timeout 3
 1Internal ctest changing into directory: /root/ci_scratch/build
 2UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
 3UpdateCTestConfiguration  from :/root/ci_scratch/build/DartConfiguration.tcl
 4Test project /root/ci_scratch/build
 5Constructing a list of tests
 6Done constructing a list of tests
 7Updating test list for fixtures
 8Added 0 tests to meet fixture requirements
 9Checking test dependency graph...
10Checking test dependency graph end
11test 1
12        Start   1: util_test_runner
13
141: 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"
151: Working Directory: /root/ci_scratch/build
161: Test timeout computed to be: 3

fanquake commented at 4:53 pm on October 1, 2024: member

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):

 0Test project /ci_container_base/ci/scratch/build-x86_64-w64-mingw32
 1        Start   1: util_test_runner
 2
 3  3/136 Test   [#5](/bitcoin-bitcoin/5/): noverify_tests .......................   Passed   86.08 sec
 4  5/136 Test   [#1](/bitcoin-bitcoin/1/): util_test_runner .....................   Passed  100.97 sec
 5 11/136 Test   [#8](/bitcoin-bitcoin/8/): bench_sanity_check_high_priority .....   Passed   15.59 sec
 6 58/136 Test   [#6](/bitcoin-bitcoin/6/): tests ................................   Passed  147.61 sec
 7135/136 Test [#136](/bitcoin-bitcoin/136/): db_tests .............................   Passed    1.69 sec
 8136/136 Test   [#4](/bitcoin-bitcoin/4/): univalue_object_test .................   Passed  216.27 sec
 9
10100% tests passed, 0 tests failed out of 136
11
12Total Test time (real) = 216.28 sec

fanquake commented at 9:11 am on October 3, 2024: member

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

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

fanquake referenced this in commit 93dda4c702 on Oct 3, 2024

fanquake referenced this in commit 56aad83307 on Oct 7, 2024

fanquake referenced this in commit 62e4516722 on Oct 7, 2024

fanquake commented at 6:56 pm on October 7, 2024: member

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

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

maflcko commented at 9:04 am on October 8, 2024: member

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.

maflcko renamed this:
~~win64-cross CI timeout after 2h~~
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`
on Oct 8, 2024

maflcko commented at 8:47 am on October 11, 2024: member

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

m3dwards referenced this in commit 8075b9fe1c on Oct 15, 2024

maflcko commented at 4:09 pm on October 28, 2024: member

Let’s move discussion to #31071

maflcko closed this on Oct 28, 2024

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

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