test: Fix intermittent issue in mining_getblocktemplate_longpoll.py #27941

Fixes #26962

Wait for the thread to have started and the RPC to have reached the node before continuing. Otherwise the test may run into a race.

For example:

 test  2023-06-23T13:10:29.245000Z TestFramework (INFO): Test that introducing a new transaction into the mempool will terminate the longpoll 
 node0 2023-06-23T13:10:29.245712Z [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43568 
 node0 2023-06-23T13:10:29.245915Z [httpworker.3] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=getblocktemplate user=__cookie__ 
 node0 2023-06-23T13:10:29.252594Z [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43568 
 node0 2023-06-23T13:10:29.254545Z [httpworker.2] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
 node0 2023-06-23T13:10:29.256530Z [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43568 
 node0 2023-06-23T13:10:29.256741Z [httpworker.1] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=sendrawtransaction user=__cookie__ 
 node0 2023-06-23T13:10:29.258033Z [httpworker.1] [validationinterface.cpp:213] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=38335600f2465c0f8bb2b86d5830a34851d86fa879800c0e1434ddfc78c42898 wtxid=c033cd3efd301c369d66cf759769159609471bd4f9efb3ee30e7209e57b74778 
 node0 2023-06-23T13:10:29.258263Z [httpworker.1] [txmempool.cpp:660] [check] [mempool] Checking mempool with 1 transactions and 1 inputs 
 node0 2023-06-23T13:10:29.258542Z [scheduler] [validationinterface.cpp:213] [operator()] [validation] TransactionAddedToMempool: txid=38335600f2465c0f8bb2b86d5830a34851d86fa879800c0e1434ddfc78c42898 wtxid=c033cd3efd301c369d66cf759769159609471bd4f9efb3ee30e7209e57b74778 
 node0 2023-06-23T13:10:29.259549Z [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43568 
 node0 2023-06-23T13:10:29.259745Z [httpworker.0] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=decoderawtransaction user=__cookie__ 
 node0 2023-06-23T13:10:29.261066Z [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52690 
 node0 2023-06-23T13:10:29.261803Z [http] [httpserver.cpp:254] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43568 
 node0 2023-06-23T13:10:29.262770Z [httpworker.2] [rpc/request.cpp:181] [parse] [rpc] ThreadRPCServer method=getblocktemplate user=__cookie__ 

(sendrawtransaction is called before getblocktemplate)

<!--e57a25ab6845829454e8d69fc972939a-->

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

<!--021abf342d371248e50ceaed478a90ca-->

Reviews

See the guideline for information on the review process.

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Approach NACK. Longpolling is supposed to work regardless of the timing here. If anything, we should explicitly trigger this race.

Can you explain this? How is longpoll supposed to work when the longpoll thread hasn't started? The thread must be initiated by the remote first, before it can be used or assumed to be working.

To clarify, there are several threads, the LongpollThread python thread, which is started at that point, and the httpworker.n Bitcoin Core thread, which may or may not (yet) have been assigned the longpoll RPC payload. The patch here ensures that the Bitcoin Core thread has been properly assigned the RPC payload first.

The longpoll request is supposed to return immediately if the conditions have been met. The token includes a reference to the transaction update state as a counter.

Github ACK https://github.com/bitcoin/bitcoin/pull/27941/commits/fa748c6f2ac2f9cac7ce42fd745ed3c3eae093b7

Seems like a commonsense fix? Can't test the RPC method if the Bitcoin Core HTTP handler hasn't booted.

The longpoll request is supposed to return immediately if the conditions have been met. The token includes a reference to the transaction update state as a counter.

Thanks, I'll take another look later.

@luke-jr I presume if this was a bug on the RPC side, it could be fixed with something like:

diff --git a/src/rpc/mining.cpp b/src/rpc/mining.cpp
index 074cecadd2..ca7d1acda8 100644
--- a/src/rpc/mining.cpp
+++ b/src/rpc/mining.cpp
@@ -742,12 +742,12 @@ static RPCHelpMan getblocktemplate()
             WAIT_LOCK(g_best_block_mutex, lock);
             while (g_best_block == hashWatchedChain && IsRPCRunning())
             {
+               // Check transactions for update
+               // without holding the mempool lock to avoid deadlocks
+               if (mempool.GetTransactionsUpdated() != nTransactionsUpdatedLastLP)
+                  break;
                 if (g_best_block_cv.wait_until(lock, checktxtime) == std::cv_status::timeout)
                 {
-                    // Timeout: Check transactions for update
-                    // without holding the mempool lock to avoid deadlocks
-                    if (mempool.GetTransactionsUpdated() != nTransactionsUpdatedLastLP)
-                        break;
                     checktxtime += std::chrono::seconds(10);
                 }
             }

However, I couldn't find any documentation about checktxtime, so I am not sure if this is the right fix. Do you mind creating this as a fix yourself, or point to some docs?

In any case, if the Bitcoin Core behavior is changed, it should be accompanied with deterministic tests. I don't think non-deterministic tests are useful, especially if they lead to a failure every time they hit the "other side" of the race.

Going to reopen for now to fix the intermittent issue, and make the tests deterministic. Happy to review a future or conflicting pull that instead changes the non-test code, or if there is documentation I missed.

ACK fa748c6f2ac2f9cac7ce42fd745ed3c3eae093b7

Seems reasonable to me to ensure that the RPC call has indeed reached the node before continuing, and should prevent races as described in #26962.