qa: Functional tests are intrinsically vulnerable to timeouts #19732

On master (3ab2582c7fe76d2839ab493512758d5601903c86) with this patch:

--- a/src/net.cpp
+++ b/src/net.cpp
@@ -2868,7 +2868,7 @@ int64_t CConnman::PoissonNextSendInbound(int64_t now, int average_interval_secon
 
 int64_t PoissonNextSend(int64_t now, int average_interval_seconds)
 {
-    return now + (int64_t)(log1p(GetRand(1ULL << 48) * -0.0000000000000035527136788 /* -1/2^48 */) * average_interval_seconds * -1000000.0 + 0.5);
+    return now + (int64_t)(log1p(((1ULL << 48) - 1) * -0.0000000000000035527136788 /* -1/2^48 */) * average_interval_seconds * -1000000.0 + 0.5);
 }
 
 CSipHasher CConnman::GetDeterministicRandomizer(uint64_t id) const

a bunch of functional tests fail due to the timeout:

feature_notifications.py                | ✖ Failed  | 62 s
interface_rest.py                       | ✖ Failed  | 63 s
interface_zmq.py                        | ✖ Failed  | 64 s
mempool_persist.py                      | ✖ Failed  | 62 s
mempool_unbroadcast.py                  | ✖ Failed  | 32 s
p2p_blocksonly.py                       | ✖ Failed  | 61 s
p2p_feefilter.py                        | ✖ Failed  | 63 s
p2p_getaddr_caching.py                  | ✖ Failed  | 62 s
p2p_permissions.py                      | ✖ Failed  | 63 s
p2p_segwit.py                           | ✖ Failed  | 69 s
p2p_tx_download.py                      | ✖ Failed  | 75 s
rpc_deprecated.py                       | ✖ Failed  | 62 s
rpc_psbt.py                             | ✖ Failed  | 65 s
rpc_psbt.py --descriptors               | ✖ Failed  | 67 s
rpc_rawtransaction.py                   | ✖ Failed  | 64 s
wallet_abandonconflict.py               | ✖ Failed  | 63 s
wallet_balance.py                       | ✖ Failed  | 63 s
wallet_basic.py                         | ✖ Failed  | 68 s
wallet_basic.py --descriptors           | ✖ Failed  | 72 s
wallet_bumpfee.py                       | ✖ Failed  | 64 s
wallet_groups.py                        | ✖ Failed  | 62 s
wallet_implicitsegwit.py                | ✖ Failed  | 62 s
wallet_listreceivedby.py                | ✖ Failed  | 62 s
wallet_listtransactions.py              | ✖ Failed  | 62 s
wallet_resendwallettransactions.py      | ✖ Failed  | 62 s

Just bumping timeout values only decreases the probability of a new timeout failure occurrence.

Suggested solution #19588 was ugly and controversial, and it has being closed for now.

Related issues:

• #18832
• #18969
• #19265
• #19311
• #19711

https://github.com/bitcoin-core/gui/pull/559 - I'm also getting a test failing in this PR, probably due to a timeout.

Is #31833 a symptom of this?

Is #31833 a symptom of this?

I don't think so, just a missing sync there.

Just to give a status update on this: The issue still exists, however:

• The CI normally has larger timeouts (due to slow runners+sanitizers+emulation), so the issue can't be seen there often, unless mocktime is used.
• Many tests opt in to immediate tx relay, as they do not test the delay specifically.

The current list of failing tests is smaller, probably:

mempool_accept_wtxid.py                                                          | ✖ Failed  | 60 s
mempool_limit.py                                                                 | ✖ Failed  | 64 s
mempool_package_rbf.py                                                           | ✖ Failed  | 64 s
mempool_persist.py                                                               | ✖ Failed  | 75 s
mempool_reorg.py                                                                 | ✖ Failed  | 10 s
p2p_blocksonly.py                                                                | ✖ Failed  | 61 s
p2p_leak_tx.py --v1transport                                                     | ✖ Failed  | 61 s
p2p_leak_tx.py --v2transport                                                     | ✖ Failed  | 61 s
p2p_private_broadcast.py                                                         | ✖ Failed  | 65 s
p2p_tx_download.py                                                               | ✖ Failed  | 29 s
p2p_tx_privacy.py                                                                | ✖ Failed  | 61 s
rpc_psbt.py                                                                      | ✖ Failed  | 84 s
wallet_balance.py                                                                | ✖ Failed  | 68 s
wallet_change_address.py                                                         | ✖ Failed  | 67 s
wallet_conflicts.py                                                              | ✖ Failed  | 64 s

The current diff to reproduce would be something like:

diff --git a/src/net_processing.cpp b/src/net_processing.cpp
index 631e968da7..0d3748f05c 100644
--- a/src/net_processing.cpp
+++ b/src/net_processing.cpp
@@ -1177,3 +1177,3 @@ std::chrono::microseconds PeerManagerImpl::NextInvToInbounds(std::chrono::micros
     if (timer < now) {
-        timer = now + m_rng.rand_exp_duration(average_interval);
+        timer = now + 12min;
     }

I wonder if a possible solution could be to:

• use immediate tx relay in the tests that do not check the delay.
• Use mocktime or a larger base-timeout for the other tests.

use immediate tx relay in the tests that do not check the delay

This seems like a good idea.