Intermittent win64 CI failure in feature_index_prune.py #25031

https://cirrus-ci.com/task/6532449864777728

Win64 native [msvc] task

 test  2022-04-29T14:22:15.843000Z TestFramework (WARNING): Not cleaning up dir C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220429_140215\feature_index_prune_242 

 test  2022-04-29T14:22:15.843000Z TestFramework (ERROR): Test failed. Test logging available at C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220429_140215\feature_index_prune_242/test_framework.log 

 test  2022-04-29T14:22:15.843000Z TestFramework (ERROR): 
 node0 stderr Error: basic block filter index best block of the index goes beyond pruned data. Please disable the index or reindex (which will download the whole blockchain again) 
 node1 stderr Error: coinstatsindex best block of the index goes beyond pruned data. Please disable the index or reindex (which will download the whole blockchain again) 
 node2 stderr Error: basic block filter index best block of the index goes beyond pruned data. Please disable the index or reindex (which will download the whole blockchain again) 

This test passes locally for me in 11-12 minutes (debian testing), albeit only with timeouts disabled test/functional/feature_index_prune.py --timeout-factor=0

I got the same at https://cirrus-ci.com/task/6464103580434432?logs=functional_tests#L3097:

test  2022-05-10T03:08:31.456000Z TestFramework (ERROR): Assertion failed 
                                Traceback (most recent call last):
                                    File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 133, in main
                                    self.run_test()
                                    File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\feature_index_prune.py", line 141, in run_test
                                    self.sync_blocks(timeout=300)
                                    File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 680, in sync_blocks
                                    assert (all([len(x.getpeerinfo()) for x in rpc_connections]))
                                AssertionError
test  2022-05-10T03:08:31.456000Z TestFramework (DEBUG): Closing down network thread 
...
<lots of lines of other tests elided>
...
test  2022-05-10T03:08:35.705000Z TestFramework (WARNING): Not cleaning up dir C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220510_024705\feature_index_prune_242 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR): Test failed. Test logging available at C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220510_024705\feature_index_prune_242/test_framework.log 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR): 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR): Hint: Call C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\combine_logs.py 'C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220510_024705\feature_index_prune_242' to consolidate all logs 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR): 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log. 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues 
test  2022-05-10T03:08:35.705000Z TestFramework (ERROR):             

(I'm not sure how to do the upload of the combined log myself, but the link above should take you to the job.)

I started debugging the same error in #24230 log https://cirrus-ci.com/task/4528289543880704 wrongly thinking it was caused by the PR (which is related to indexing) after it happened twice in a row.

But it seems like there is just a race condition in the test. The test starts 4 nodes, then shut down the first 3, and restarts those three with a -connect option to connect them to 4th node. Then it immediately calls sync_blocks which fails because the getpeerinfo for one of the nodes is empty.

Maybe a fix is to add:

self.wait_until(lambda: all(len(n.getpeerinfo()) for n in self.nodes))

before the sync_blocks call, but I'm not sure.

Note the stack trace:

Traceback (most recent call last):

  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 133, in main

    self.run_test()

  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\feature_index_prune.py", line 141, in run_test

    self.sync_blocks(timeout=300)

  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 680, in sync_blocks

    assert (all([len(x.getpeerinfo()) for x in rpc_connections]))

AssertionError

@fjahr could weigh in perhaps. The sync_blocks call was added in de08932efa953e9a237cbf879460488ad8947411 from #21726 which was merged about 2 weeks ago

Thanks for the ping! I was unable to reproduce the issue locally but I agree with the analysis by @ryanofsky that there is a race going on between the establishment of the connection and that sanity check line in sync_blocks that fails.

I think the one-liner suggested would work I think but I think I would prefer to use the addconnection RPC which should have the same effect but the code is easier to read and debug. Suggested in #25123.

Can reproduce on master with a diff.

diff --git a/src/net.cpp b/src/net.cpp
index 1c775f9a3f..e2ddb7fe3b 100644
--- a/src/net.cpp
+++ b/src/net.cpp
@@ -1913,6 +1913,7 @@ void CConnman::ThreadOpenConnections(const std::vector<std::string> connect)
     // Connect to specific addresses
     if (!connect.empty())
     {
+        UninterruptibleSleep(1s);
         for (int64_t nLoop = 0;; nLoop++)
         {
             ProcessAddrFetch();