win64-cross CI timeout after 2h

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

win64-cross CI timeout after 2h #30969