p2p_permissions intermittent timeout #26852

wget https://drahtbot.space/temp_scratch/p2p_permissions.tar.xz
tar -xvf p2p_permissions.tar.xz
test/functional/combine_logs.py -c ./p2p_permissions_15/ | tail -131 | head -33
 test  2023-01-09T13:02:23.385000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                               self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
                                   '''
 test  2023-01-09T13:02:23.386000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
                                       self.run_test()
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_permissions.py", line 34, in run_test
                                       self.check_tx_relay()
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_permissions.py", line 128, in check_tx_relay
                                       self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 732, in wait_until
                                       return wait_until_helper(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
                                     File "/root/bitcoin-core/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 281, in wait_until_helper
                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
                                   AssertionError: Predicate ''''
                                               self.wait_until(lambda: txid in self.nodes[0].getrawmempool())
                                   ''' not true after 2400.0 seconds

Excerpt from when the bug occurs:

...
 test  2023-01-09T12:22:23.228000Z TestFramework (DEBUG): Check that node[1] will send the tx to node[0] even though it is already in the mempool
 node1 2023-01-09T12:22:23.228783Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 node1 2023-01-09T12:22:23.228986Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 node0 2023-01-09T12:22:23.231535Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40640
 node0 2023-01-09T12:22:23.231734Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 node1 2023-01-09T12:22:23.233267Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 node1 2023-01-09T12:22:23.233445Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addnode user=__cookie__
 node1 2023-01-09T12:22:23.233642Z [httpworker.1] [net.cpp:456] [ConnectNode] [net:debug] trying connection 127.0.0.1:11180 lastseen=0.0hrs
 node1 2023-01-09T12:22:23.234022Z [httpworker.1] [net.cpp:2763] [CNode] [net] Added connection peer=1
 node0 2023-01-09T12:22:23.234192Z [net] [net.cpp:2763] [CNode] [net] Added connection peer=1
 node1 2023-01-09T12:22:23.234279Z [httpworker.1] [net.cpp:2776] [PushMessage] [net] sending version (114 bytes) peer=1
 node0 2023-01-09T12:22:23.234381Z [net] [net.cpp:1037] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:42510 accepted
 node1 2023-01-09T12:22:23.234458Z [httpworker.1] [net_processing.cpp:1396] [PushNodeVersion] [net] send version message: version 70016, blocks=100, txrelay=1, peer=1
 node0 2023-01-09T12:22:23.234721Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: version (114 bytes) peer=1
 node0 2023-01-09T12:22:23.234817Z [msghand] [net.cpp:2776] [PushMessage] [net] sending version (114 bytes) peer=1
 node0 2023-01-09T12:22:23.234991Z [msghand] [net_processing.cpp:1396] [PushNodeVersion] [net] send version message: version 70016, blocks=100, txrelay=1, peer=1
 node1 2023-01-09T12:22:23.235034Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 node0 2023-01-09T12:22:23.235044Z [msghand] [net.cpp:2776] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1
 node0 2023-01-09T12:22:23.235153Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1
 node1 2023-01-09T12:22:23.235220Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 node0 2023-01-09T12:22:23.237171Z [msghand] [net.cpp:2776] [PushMessage] [net] sending verack (0 bytes) peer=1
 node0 2023-01-09T12:22:23.237312Z [msghand] [net_processing.cpp:3352] [ProcessMessage] [net] receive version message: /Satoshi:24.99.0(testnode1)/: version 70016, blocks=100, us=[::]:0, txrelay=1, peer=1
 node1 2023-01-09T12:22:23.277409Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: version (114 bytes) peer=1
 node1 2023-01-09T12:22:23.277514Z [msghand] [net.cpp:2776] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1
 node1 2023-01-09T12:22:23.277691Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1
 node0 2023-01-09T12:22:23.278071Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1
 node0 2023-01-09T12:22:23.278225Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: sendaddrv2 (0 bytes) peer=1
 node1 2023-01-09T12:22:23.279894Z [msghand] [net.cpp:2776] [PushMessage] [net] sending verack (0 bytes) peer=1
 node1 2023-01-09T12:22:23.288745Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 node1 2023-01-09T12:22:23.288981Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 node1 2023-01-09T12:22:23.292375Z [msghand] [net.cpp:2776] [PushMessage] [net] sending getaddr (0 bytes) peer=1
 node0 2023-01-09T12:22:23.292524Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: verack (0 bytes) peer=1
 node1 2023-01-09T12:22:23.292533Z [msghand] [net_processing.cpp:3352] [ProcessMessage] [net] receive version message: /Satoshi:24.99.0(testnode0)/: version 70016, blocks=100, us=[::]:0, txrelay=1, peer=1
 node0 2023-01-09T12:22:23.292608Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1
 node1 2023-01-09T12:22:23.292609Z [msghand] [timedata.cpp:57] [AddTimeData] [net] added time data, samples 2, offset +0 (+0 minutes)
 node0 2023-01-09T12:22:23.292856Z [msghand] [net.cpp:2776] [PushMessage] [net] sending ping (8 bytes) peer=1
 node0 2023-01-09T12:22:23.293028Z [msghand] [net.cpp:2776] [PushMessage] [net] sending getheaders (613 bytes) peer=1
 node0 2023-01-09T12:22:23.293179Z [msghand] [net_processing.cpp:5416] [SendMessages] [net] initial getheaders (99) to peer=1 (startheight:100)
 node0 2023-01-09T12:22:23.293354Z [msghand] [net.cpp:2776] [PushMessage] [net] sending feefilter (8 bytes) peer=1
 node0 2023-01-09T12:22:23.293634Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: getaddr (0 bytes) peer=1
 node0 2023-01-09T12:22:23.294846Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40640
 node0 2023-01-09T12:22:23.295037Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 node1 2023-01-09T12:22:23.297221Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:48608
 node1 2023-01-09T12:22:23.297634Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 node1 2023-01-09T12:22:23.298425Z [httpworker.0] [logging/timer.h:57] [Log] [lock] Enter: lock contention m_peer_mutex, net_processing.cpp:1537 started
 node1 2023-01-09T12:22:23.298514Z [httpworker.0] [logging/timer.h:57] [Log] [lock] Enter: lock contention m_peer_mutex, net_processing.cpp:1537 completed (27μs)
 node0 2023-01-09T12:22:23.300825Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40640
 node0 2023-01-09T12:22:23.300993Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__
 test  2023-01-09T12:22:23.303000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11181: msg_tx(tx=CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=d925626975d73bd782c38ce1eed34aed6eee030680271e7982197873289c747f n=0) scriptSig= nSequence=4294967295)] vout=[CTxOut(nValue=5.00000000 scriptPubKey=00204ae81572f06e1b88fd5ced7a1a000945432e83e1551e6f721ee9c00b8cc33260)] wit=CTxWitness(CScriptWitness(51)) nLockTime=0))
 test  2023-01-09T12:22:23.303000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11181: msg_ping(nonce=00000003)
 node1 2023-01-09T12:22:23.303821Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: tx (99 bytes) peer=0
 test  2023-01-09T12:22:23.304000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:11181: msg_pong(nonce=00000003)
 node1 2023-01-09T12:22:23.304012Z [msghand] [net_processing.cpp:4020] [ProcessMessage] Force relaying tx 15d85d00f224f10cecaa12a6eba4994045f2abbe0f929e1c16bba06cfc0ddc39 from peer=0
 node1 2023-01-09T12:22:23.304267Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1
 node1 2023-01-09T12:22:23.304402Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: sendaddrv2 (0 bytes) peer=1
 node1 2023-01-09T12:22:23.304502Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: ping (8 bytes) peer=0
 node1 2023-01-09T12:22:23.304562Z [msghand] [net.cpp:2776] [PushMessage] [net] sending pong (8 bytes) peer=0
 node1 2023-01-09T12:22:23.305109Z [msghand] [net_processing.cpp:3155] [ProcessMessage] [net] received: verack (0 bytes) peer=1
 node1 2023-01-09T12:22:23.305702Z [msghand] [net_processing.cpp:3395] [ProcessMessage] New outbound peer connected: version: 70016, blocks=100, peer=1 (manual)
 node1 2023-01-09T12:22:23.305759Z [msghand] [net.cpp:2776] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1
 node1 2023-01-09T12:22:23.305930Z [msghand] [net.cpp:2776] [PushMessage] [net] sending ping (8 bytes) peer=1
...