intermittent issue in p2p_orphan_handling.py #31700

issue maflcko openend this issue on January 21, 2025
  1. maflcko commented at 2:07 pm on January 21, 2025: member

    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

      0 test  2025-01-21T11:21:24.017000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14372 
  1 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)]) 
  2 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__ 
  3 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 
  4 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__ 
  5 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 
  6 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 
  7 node0 2025-01-21T11:21:24.017449Z (mocktime: 2025-01-27T11:30:10Z) [net] [net.cpp:2188] [SocketHandlerConnected] [net] socket closed, disconnecting peer=23 
  8 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 
  9 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 
 10 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__ 
 11 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 
 12 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 
 13 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)]) 
 14 test  2025-01-21T11:28:04.173000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
 15                                           def test_function():
 16                                               if check_connected:
 17                                                   assert self.is_connected
 18                                               return test_function_in()
 19                                   '''
 20 test  2025-01-21T11:28:04.176000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress` 
 21 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 
 22 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__ 
 23 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 
 24 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)] 
 25 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)] 
 26 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)] 
 27 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)] 
 28 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) 
 29 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 
 30 node0 2025-01-21T11:28:04.182065Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validationinterface.cpp:255] [NewPoWValidBlock] [validation] NewPoWValidBlock: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 
 31 node0 2025-01-21T11:28:04.182999Z (mocktime: 2025-01-27T11:30:10Z) [httpworker.1] [validation.cpp:3187] [ConnectTip] [bench]   - Using cached block 
 32 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 
 33 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)] 
 34 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)] 
 35 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)] 
 36 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)] 
 37 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)] 
 38 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)] 
 39 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 
 40 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)] 
 41 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)] 
 42 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)] 
 43 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 
 44 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 
 45 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) 
 46 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)] 
 47 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)] 
 48 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 
 49 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 
 50 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 
 51 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) 
 52 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 
 53 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 
 54 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 
 55 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) 
 56 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 
 57 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 
 58 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)]) 
 59 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)]) 
 60 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 
 61 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__ 
 62 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 
 63 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 
 64 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 
 65 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 
 66 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) 
 67 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 
 68 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__ 
 69 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 
 70 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__ 
 71 test  2025-01-21T11:28:04.191000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:14372 
 72 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 
 73 node0 2025-01-21T11:28:04.191893Z (mocktime: 2025-01-27T11:30:10Z) [net] [net.cpp:2188] [SocketHandlerConnected] [net] socket closed, disconnecting peer=24 
 74 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__ 
 75 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 
 76 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 
 77 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 
 78 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 
 79 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__ 
 80 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 
 81 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__ 
 82 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 
 83 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__ 
 84 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 
 85 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__ 
 86 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 
 87 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) 
 88 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 
 89 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) 
 90 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 
 91 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 
 92 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... 
 93 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) 
 94 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 
 95 node0 2025-01-21T11:28:04.199489Z (mocktime: 2025-01-27T23:30:10Z) [scheduler] [validationinterface.cpp:245] [operator()] [validation] ChainStateFlushed: block hash=077bf058147704114b908875b7fbfa54065dfe633c6e904276222f6284c18662 
 96 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 
 97 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__ 
 98 test  2025-01-21T11:28:04.203000Z TestFramework (ERROR): Assertion failed 
 99                                   Traceback (most recent call last):
100                                     File "/Users/runner/work/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 135, in main
101                                       self.run_test()
102                                       ~~~~~~~~~~~~~^^
103                                     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
104                                       self.test_parents_change()
105                                       ~~~~~~~~~~~~~~~~~~~~~~~~^^
106                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build-aarch64-apple-darwin23.6.0/test/functional/p2p_orphan_handling.py", line 55, in wrapper
107                                       func(self)
108                                       ~~~~^^^^^^
109                                     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
110                                       peer2.wait_for_parent_requests([int(parent_peekaboo_AB["txid"], 16), int(parent_missing["txid"], 16)])
111                                       ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
112                                     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
113                                       self.wait_until(test_function, timeout=10)
114                                       ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^
115                                     File "/Users/runner/work/bitcoin/bitcoin/test/functional/test_framework/p2p.py", line 594, in wait_until
116                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
117                                       ~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
118                                     File "/Users/runner/work/bitcoin/bitcoin/test/functional/test_framework/util.py", line 317, in wait_until_helper_internal
119                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
120                                   AssertionError: Predicate ''''
121                                           def test_function():
122                                               if check_connected:
123                                                   assert self.is_connected
124                                               return test_function_in()
125                                   ''' not true after 400.0 seconds
126 test  2025-01-21T11:28:04.208000Z TestFramework (DEBUG): Closing down network thread 
127 test  2025-01-21T11:28:04.307000Z TestFramework (INFO): Stopping nodes 
128 test  2025-01-21T11:28:04.308000Z TestFramework.node0 (DEBUG): Stopping node
  2. maflcko added the label CI failed on Jan 21, 2025
  3. hodlinator commented at 8:46 am on January 30, 2025: contributor
    Another case: https://github.com/hodlinator/bitcoin/actions/runs/13042105883/job/36386032546#step:7:15916
  4. maflcko added this to the milestone 29.0 on Feb 18, 2025
  5. maflcko removed this from the milestone 29.0 on Feb 18, 2025
  6. maflcko commented at 1:10 pm on February 24, 2025: member
    Another from a local run: https://drahtbot.space/temp_scratch/p2p_o_h_208.tar.zstd
  7. maflcko commented at 4:34 pm on March 12, 2025: member
    https://cirrus-ci.com/task/5838171738472448?logs=ci#L2741
  8. Sjors commented at 11:09 am on March 13, 2025: member

    cc orphanage fans @glozow, @sipa, @mzumsande

    #31829 significantly overhauls this test, so not sure if a fix would conflict with that?

  9. mzumsande commented at 3:19 pm on March 13, 2025: contributor

    so not sure if a fix would conflict with that?

    Haven’t looked into this one yet, but it shouldn’t really matter if (#31829) conflicts or not - a fix should have priority, if possible be included in 29.0, so that we don’t have a release with known intermittent failures.

  10. mzumsande commented at 9:54 pm on March 13, 2025: contributor

    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.

    That is not the problem here, because the delay for requesting txns is actually constant and not randomized / exponentially distributed.

    Possibly the getdata was split into two, so the check didn’t pick it up, because it assumes it to happen in one msg

    Yes, this is what’s happening in the failed runs. I think the reason is that we call peer_disconnect() but don’t wait for the disconnected to be finished, so we may bump the mocktime before that has happened, resulting in the GETDATA to be split over two messages.

    See #32063 for a fix.

  11. fanquake closed this on Mar 16, 2025
  12. pull[bot] referenced this in commit 70a0ee89c6 on Mar 16, 2025
  13. tnndbtc commented at 7:50 pm on March 17, 2025: none
    @maflcko Even with @mzumsande ’s fix in , I am able to add a one second sleep in src/net.cpp:CConnman::DisconnectNodes() to 100% reproduce the issue on Mac with Apple M1 chipset with OS Sequoia 15.1.1 with --timeout-factor=1.1. For more details, please checkout #32063 (comment)
  14. maflcko reopened this on Mar 17, 2025
  15. maflcko commented at 3:34 pm on March 18, 2025: member

    @tnndbtc Thank you for the exact diff to reproduce. This makes it easier to test!

    I don’t know how to fix this class of bug completely, but this one instance can simply be fixed by syncing with the net thread. The issue is that net_processing still has a stale reference to the disconnected node and is waiting for the net thread to delete it. There is no direct way to sync with the Bitcoin Core net thread from outside the process, but as a hacky workaround, one can add some bytes to the buffer and wait for them to be consumed by the net thread. This should ensure the disconnect happened before the message bytes are fully handled.

    See this diff, which should pass:

     0diff --git a/src/net.cpp b/src/net.cpp
 1index 735985a841..2bb6db0cf7 100644
 2--- a/src/net.cpp
 3+++ b/src/net.cpp
 4@@ -1965,6 +1965,9 @@ void CConnman::DisconnectNodes()
 5             // Destroy the object only after other threads have stopped using it.
 6             if (pnode->GetRefCount() <= 0) {
 7                 m_nodes_disconnected.remove(pnode);
 8+
 9+                std::this_thread::sleep_for(std::chrono::seconds(1)); // SLEEP for 1 second to 100% reproduce the issue
10+
11                 DeleteNode(pnode);
12             }
13         }
14diff --git a/test/functional/p2p_orphan_handling.py b/test/functional/p2p_orphan_handling.py
15index ac8b6fd705..e839b2d987 100755
16--- a/test/functional/p2p_orphan_handling.py
17+++ b/test/functional/p2p_orphan_handling.py
18@@ -789,6 +789,7 @@ class OrphanHandlingTest(BitcoinTestFramework):
19         # Disconnect peer1. peer2 should become the new candidate for orphan resolution.
20         peer1.peer_disconnect()
21         self.wait_until(lambda: node.num_test_p2p_connections() == 1)
22+        peer2.sync_with_ping()  # Sync with the 'net' thread which completes the disconnection fully
23         node.bumpmocktime(TXREQUEST_TIME_SKIP)
24         self.wait_until(lambda: len(node.getorphantxs(verbosity=2)[0]["from"]) == 1)
25         # Both parents should be requested, now that they are both missing.
  16. maflcko commented at 4:07 pm on March 18, 2025: member
    An alternative fix would be to adjust wait_for_parent_requests to accept any order and any sequence of messages, but this may be a larger diff.
  17. fanquake closed this on Mar 21, 2025


maflcko hodlinator Sjors mzumsande tnndbtc

Labels
CI failed

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2025-03-31 09:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me