Repository: bitcoin
Issue: intermittent issue in p2p_orphan_handling.py
Labels: CI failed

Looks like the test may overall intermittently fail, because it assumes the tx delay isn't exponentially distributed, but has a constant delay, sufficient for the test to pass.

I think it would be better to use mocktime to halt the test when needed, so that it can even pass when the delay is zero (or close to it).

I haven't looked in detail whether this is the same, but there was one instance in the CI: (Possibly the getdata was split into two, so the check didn't pick it up, because it assumes it to happen in one msg?)

https://github.com/bitcoin/bitcoin/actions/runs/12885576442/job/35924329366?pr=25832#step:7:15913

```
 test  2025-01-21T11:21:24.017000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14372 
 test  2025-01-21T11:21:24.017000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:14372: msg_getdata(inv=[CInv(type=WitnessTx hash=16df2774cb507f967e367838f263d09c647bcc7818d5c45d886c0ee5b8f45ac7)]) 
 node0 2025-01-21T11:21:24.017006Z (mocktime: 2025-01-27T11:30:06Z) [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getorphantxs user=__cookie__ 
 node0 2025-01-21T11:21:24.017297Z (mocktime: 2025-01-27T11:30:06Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:21:24.017316Z (mocktime: 2025-01-27T11:30:06Z) [httpworker.14] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2025-01-21T11:21:24.017368Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [node/txdownloadman_impl.cpp:276] [GetRequestsToSend] [net] Requesting tx 16df2774cb507f967e367838f263d09c647bcc7818d5c45d886c0ee5b8f45ac7 peer=24 
 node0 2025-01-21T11:21:24.017377Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net.cpp:3874] [PushMessage] [net] sending getdata (37 bytes) peer=24 
 node0 2025-01-21T11:21:24.017449Z (mocktime: 2025-01-27T11:30:10Z) [net] [net.cpp:2188] [SocketHandlerConnected] [net] socket closed, disconnecting peer=23 
 node0 2025-01-21T11:21:24.017467Z (mocktime: 2025-01-27T11:30:10Z) [net] [net_processing.cpp:1633] [FinalizeNode] [net] Cleared nodestate for peer=23 
 node0 2025-01-21T11:21:24.017701Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:21:24.017722Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.15] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getorphantxs user=__cookie__ 
 node0 2025-01-21T11:21:24.221913Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [node/txdownloadman_impl.cpp:276] [GetRequestsToSend] [net] Requesting tx f2777bc29da8d92e6090c69775a12bc7df96a4da2554d086749f8f854872d133 peer=24 
 node0 2025-01-21T11:21:24.221941Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net.cpp:3874] [PushMessage] [net] sending getdata (37 bytes) peer=24 
 test  2025-01-21T11:21:24.222000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:14372: msg_getdata(inv=[CInv(type=WitnessTx hash=f2777bc29da8d92e6090c69775a12bc7df96a4da2554d086749f8f854872d133)]) 
 test  2025-01-21T11:28:04.173000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           def test_function():
                                               if check_connected:
                                                   assert self.is_connected
                                               return test_function_in()
                                   '''
 test  2025-01-21T11:28:04.176000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress` 
 node0 2025-01-21T11:28:04.179438Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.180169Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__ 
 node0 2025-01-21T11:28:04.180973Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [node/miner.cpp:161] [CreateNewBlock] CreateNewBlock(): block weight: 1319 txs: 1 fees: 31200 sigops 400 
 node0 2025-01-21T11:28:04.181211Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2527] [ConnectBlock] [bench]     - Sanity checks: 0.01ms [0.00s (0.00ms/blk)] 
 node0 2025-01-21T11:28:04.181552Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2629] [ConnectBlock] [bench]     - Fork checks: 0.38ms [0.00s (0.01ms/blk)] 
 node0 2025-01-21T11:28:04.181650Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2722] [ConnectBlock] [bench]       - Connect 2 transactions: 0.10ms (0.048ms/tx, 0.095ms/txin) [0.00s (0.01ms/blk)] 
 node0 2025-01-21T11:28:04.181716Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2744] [ConnectBlock] [bench]     - Verify 1 txins: 0.16ms (0.163ms/txin) [0.01s (0.02ms/blk)] 
 node0 2025-01-21T11:28:04.181756Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [node/miner.cpp:180] [CreateNewBlock] [bench] CreateNewBlock() packages: 0.18ms (1 packages, 0 updated descendants), validity: 0.89ms (total 1.07ms) 
 node0 2025-01-21T11:28:04.181838Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:4428] [AcceptBlockHeader] Saw new header hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 height=394 
 node0 2025-01-21T11:28:04.182065Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:255] [NewPoWValidBlock] [validation] NewPoWValidBlock: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 
 node0 2025-01-21T11:28:04.182999Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3187] [ConnectTip] [bench]   - Using cached block 
 node0 2025-01-21T11:28:04.183046Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3197] [ConnectTip] [bench]   - Load block from disk: 0.03ms 
 node0 2025-01-21T11:28:04.183078Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2527] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
 node0 2025-01-21T11:28:04.183121Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2629] [ConnectBlock] [bench]     - Fork checks: 0.04ms [0.00s (0.01ms/blk)] 
 node0 2025-01-21T11:28:04.183176Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2722] [ConnectBlock] [bench]       - Connect 2 transactions: 0.05ms (0.026ms/tx, 0.051ms/txin) [0.00s (0.01ms/blk)] 
 node0 2025-01-21T11:28:04.183210Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2744] [ConnectBlock] [bench]     - Verify 1 txins: 0.09ms (0.088ms/txin) [0.01s (0.02ms/blk)] 
 node0 2025-01-21T11:28:04.183460Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2759] [ConnectBlock] [bench]     - Write undo data: 0.25ms [0.04s (0.11ms/blk)] 
 node0 2025-01-21T11:28:04.183491Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:2774] [ConnectBlock] [bench]     - Index writing: 0.03ms [0.00s (0.01ms/blk)] 
 node0 2025-01-21T11:28:04.183525Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:250] [BlockChecked] [validation] BlockChecked: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 state=Valid 
 node0 2025-01-21T11:28:04.183575Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3216] [ConnectTip] [bench]   - Connect total: 0.54ms [0.06s (0.15ms/blk)] 
 node0 2025-01-21T11:28:04.183609Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3225] [ConnectTip] [bench]   - Flush: 0.03ms [0.00s (0.00ms/blk)] 
 node0 2025-01-21T11:28:04.183634Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3235] [ConnectTip] [bench]   - Writing chainstate: 0.02ms [0.00s (0.00ms/blk)] 
 node0 2025-01-21T11:28:04.183680Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [txmempool.cpp:1074] [RemoveUnbroadcastTx] [mempool] Removed ded4025fc122f8892f8e1a3ee818c85275956a77843be62b6989b1c3ff5f2e46 from set of unbroadcast txns before confirmation that txn was sent out 
 node0 2025-01-21T11:28:04.183747Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:227] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=394 txs removed=1 
 node0 2025-01-21T11:28:04.183850Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3006] [UpdateTipLog] UpdateTip: new best=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 height=394 version=0x30000000 log2_work=9.625709 tx=612 date='2025-01-27T11:30:10Z' progress=1.000000 cache=0.3MiB(5txo) 
 node0 2025-01-21T11:28:04.183901Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3251] [ConnectTip] [bench]   - Connect postprocess: 0.27ms [0.01s (0.02ms/blk)] 
 node0 2025-01-21T11:28:04.183939Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3255] [ConnectTip] [bench] - Connect block: 0.90ms [0.07s (0.18ms/blk)] 
 node0 2025-01-21T11:28:04.184008Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [txmempool.cpp:700] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
 node0 2025-01-21T11:28:04.184059Z (mocktime: 2025-01-27T11:30:10Z) [scheduler] [validationinterface.cpp:227] [operator()] [validation] MempoolTransactionsRemovedForBlock: block height=394 txs removed=1 
 node0 2025-01-21T11:28:04.184177Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:217] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 block height=394 
 node0 2025-01-21T11:28:04.184218Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:182] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 fork block hash=4662d66c50b6a655b6971c547619516417c1b422d0718ee24d30f56502410ca3 (in IBD=false) 
 node0 2025-01-21T11:28:04.184286Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:187] [ActiveTipChange] [validation] ActiveTipChange: new block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 block height=394 
 node0 2025-01-21T11:28:04.184454Z (mocktime: 2025-01-27T11:30:10Z) [scheduler] [policy/fees.cpp:711] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 1 block txs, since last block 0 of 3 tracked, mempool map size 0, max target 11 from current 
 node0 2025-01-21T11:28:04.184501Z (mocktime: 2025-01-27T11:30:10Z) [scheduler] [validationinterface.cpp:217] [operator()] [validation] BlockConnected: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 block height=394 
 node0 2025-01-21T11:28:04.185563Z (mocktime: 2025-01-27T11:30:10Z) [scheduler] [validationinterface.cpp:182] [operator()] [validation] UpdatedBlockTip: new block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 fork block hash=4662d66c50b6a655b6971c547619516417c1b422d0718ee24d30f56502410ca3 (in IBD=false) 
 node0 2025-01-21T11:28:04.185654Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net_processing.cpp:5649] [SendMessages] [net] SendMessages: sending inv peer=24 hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 
 node0 2025-01-21T11:28:04.185696Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net.cpp:3874] [PushMessage] [net] sending inv (37 bytes) peer=24 
 test  2025-01-21T11:28:04.187000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:14372: msg_inv(inv=[CInv(type=Block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662)]) 
 test  2025-01-21T11:28:04.187000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:14372: msg_getdata(inv=[CInv(type=Block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662)]) 
 node0 2025-01-21T11:28:04.188203Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.188325Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.0] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2025-01-21T11:28:04.188566Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net_processing.cpp:3380] [ProcessMessage] [net] received: getdata (37 bytes) peer=24 
 node0 2025-01-21T11:28:04.188622Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net_processing.cpp:3990] [ProcessMessage] [net] received getdata (1 invsz) peer=24 
 node0 2025-01-21T11:28:04.188660Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net_processing.cpp:3993] [ProcessMessage] [net] received getdata for: block 077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 peer=24 
 node0 2025-01-21T11:28:04.188706Z (mocktime: 2025-01-27T11:30:10Z) [msghand] [net.cpp:3874] [PushMessage] [net] sending block (311 bytes) peer=24 
 test  2025-01-21T11:28:04.189000Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:14372: msg_block(block=CBlock(nVersion=805306368 hashPrevBlock=4662d66c50b6a655b6971c547619516417c1b422d0718ee24d30f56502410ca3 hashMerkleRoot=b7943c8d36e59a4b8f042e99f55b71e9da78debc337f2520ac30ffb98be501ff nTime=Mon Jan 27 11:30:10 2025 nBits=207fffff nNonce=00000003 vtx=[CTransaction(version=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=028a0100 nSequence=4294967295)] vout=[CTxOut(nValue=12.50031200 scriptPubKey=76a9142b4... (msg truncated) 
 node0 2025-01-21T11:28:04.189053Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.189130Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.3] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2025-01-21T11:28:04.190512Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.190644Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.2] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 test  2025-01-21T11:28:04.191000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14372 
 node0 2025-01-21T11:28:04.191805Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.191893Z (mocktime: 2025-01-27T11:30:10Z) [net] [net.cpp:2188] [SocketHandlerConnected] [net] socket closed, disconnecting peer=24 
 node0 2025-01-21T11:28:04.191978Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.5] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node0 2025-01-21T11:28:04.192224Z (mocktime: 2025-01-27T11:30:10Z) [net] [txorphanage.cpp:93] [EraseTx] [txpackages]    removed orphan tx 55ae42d3c30e22ed3fd70b24bbeb214e67fca0420f1fdc8a508a88b4e386af94 (wtxid=9477fadf8dc360b951c9facff7a0be4c4cf8a7158368d64c963a4765fb1a957c) after 8s 
 node0 2025-01-21T11:28:04.192252Z (mocktime: 2025-01-27T11:30:10Z) [net] [txorphanage.cpp:120] [EraseForPeer] [txpackages] Erased 1 orphan transaction(s) from peer=24 
 node0 2025-01-21T11:28:04.192263Z (mocktime: 2025-01-27T11:30:10Z) [net] [net_processing.cpp:1633] [FinalizeNode] [net] Cleared nodestate for peer=24 
 node0 2025-01-21T11:28:04.192474Z (mocktime: 2025-01-27T11:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.192514Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.4] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2025-01-21T11:28:04.192867Z (mocktime: 2025-01-27T23:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.192901Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.6] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getorphantxs user=__cookie__ 
 node0 2025-01-21T11:28:04.193191Z (mocktime: 2025-01-27T23:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.193223Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.7] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2025-01-21T11:28:04.194015Z (mocktime: 2025-01-27T23:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.194065Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=scantxoutset user=__cookie__ 
 node0 2025-01-21T11:28:04.194263Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block and undo data to disk started 
 node0 2025-01-21T11:28:04.196980Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block and undo data to disk completed (2.69ms) 
 node0 2025-01-21T11:28:04.197024Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block index to disk started 
 node0 2025-01-21T11:28:04.198904Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [logging/timer.h:58] [Log] [bench] FlushStateToDisk: write block index to disk completed (1.87ms) 
 node0 2025-01-21T11:28:04.198947Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [logging/timer.h:58] [Log] [bench] FlushStateToDisk: write coins cache to disk (5 coins, 256KiB) started 
 node0 2025-01-21T11:28:04.198985Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [txdb.cpp:148] [BatchWrite] [coindb] Writing final batch of 0.00 MiB 
 node0 2025-01-21T11:28:04.199390Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [txdb.cpp:150] [BatchWrite] [coindb] Committed 3 changed transaction outputs (out of 3) to coin database... 
 node0 2025-01-21T11:28:04.199415Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [logging/timer.h:58] [Log] [bench] FlushStateToDisk: write coins cache to disk (5 coins, 256KiB) completed (0.46ms) 
 node0 2025-01-21T11:28:04.199431Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.8] [validationinterface.cpp:245] [ChainStateFlushed] [validation] Enqueuing ChainStateFlushed: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 
 node0 2025-01-21T11:28:04.199489Z (mocktime: 2025-01-27T23:30:10Z) [scheduler] [validationinterface.cpp:245] [operator()] [validation] ChainStateFlushed: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 
 node0 2025-01-21T11:28:04.202632Z (mocktime: 2025-01-27T23:30:10Z) [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:49580 
 node0 2025-01-21T11:28:04.202704Z (mocktime: 2025-01-27T23:30:10Z) [httpworker.10] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 test  2025-01-21T11:28:04.203000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/Users/runner/work/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 135, in main
                                       self.run_test()
                                       ~~~~~~~~~~~~~^^
                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build-aarch64-apple-darwin23.6.0/test/functional/p2p_orphan_handling.py", line 820, in run_test
                                       self.test_parents_change()
                                       ~~~~~~~~~~~~~~~~~~~~~~~~^^
                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build-aarch64-apple-darwin23.6.0/test/functional/p2p_orphan_handling.py", line 55, in wrapper
                                       func(self)
                                       ~~~~^^^^^^
                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build-aarch64-apple-darwin23.6.0/test/functional/p2p_orphan_handling.py", line 791, in test_parents_change
                                       peer2.wait_for_parent_requests([int(parent_peekaboo_AB["txid"], 16), int(parent_missing["txid"], 16)])
                                       ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build-aarch64-apple-darwin23.6.0/test/functional/p2p_orphan_handling.py", line 99, in wait_for_parent_requests
                                       self.wait_until(test_function, timeout=10)
                                       ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                     File "/Users/runner/work/bitcoin/bitcoin/test/functional/test_framework/p2p.py", line 594, in wait_until
                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
                                       ~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                     File "/Users/runner/work/bitcoin/bitcoin/test/functional/test_framework/util.py", line 317, in wait_until_helper_internal
                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
                                   AssertionError: Predicate ''''
                                           def test_function():
                                               if check_connected:
                                                   assert self.is_connected
                                               return test_function_in()
                                   ''' not true after 400.0 seconds
 test  2025-01-21T11:28:04.208000Z TestFramework (DEBUG): Closing down network thread 
 test  2025-01-21T11:28:04.307000Z TestFramework (INFO): Stopping nodes 
 test  2025-01-21T11:28:04.308000Z TestFramework.node0 (DEBUG): Stopping node