Issue in `p2p_ibd_stalling.py` under Valgrind #27208

issue fanquake opened this issue on March 6, 2023
  1. fanquake commented at 9:29 AM on March 6, 2023: member

    At 40c6c85c05812ee8bf824b639307b1ac17a001c4 with the native_valgrind job:

     test  2023-03-05T21:26:43.074000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
 node0 2023-03-05T21:26:43.265731Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
 node0 2023-03-05T21:26:43.267295Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 node0 2023-03-05T21:26:43.269862Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40916 
 node0 2023-03-05T21:26:43.271568Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
 node0 2023-03-05T21:26:55.588032Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-05T21:26:55.709062Z [httpworker.0] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12173 lastseen=0.0hrs 
 node0 2023-03-05T21:26:55.731504Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=2 
 test  2023-03-05T21:27:43.097000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           test_function = lambda: self.is_connected
                                   '''
 test  2023-03-05T21:27:43.097000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
                                       self.run_test()
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 77, in run_test
                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 663, in add_outbound_p2p_connection
                                       p2p_conn.wait_for_connect()
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 467, in wait_for_connect
                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
                                     File "/home/ubuntu/ci_scratch/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 ''''
                                           test_function = lambda: self.is_connected
                                   ''' not true after 60.0 seconds
 test  2023-03-05T21:27:43.102000Z TestFramework (DEBUG): Closing down network thread 
 test  2023-03-05T21:27:53.123000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
                                   '''
 node0 2023-03-05T21:28:08.198208Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=1 from eviction 
 node0 2023-03-05T21:28:08.201820Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=1
  2. fanquake added the label Bug on Mar 6, 2023
  3. fanquake added the label Tests on Mar 6, 2023
  4. maflcko commented at 9:31 AM on March 6, 2023: member

    What did you set the timeout factor to? Is there a combined log or similar?

  5. fanquake commented at 9:58 AM on March 7, 2023: member

    What did you set the timeout factor to?

    I didn't change it at all. Will get you a log.

  6. fanquake commented at 7:25 PM on March 7, 2023: member

    Is there a combined log or similar?

    ............................                                                                                                            170/256 - p2p_ibd_stalling.py failed, Duration: 134 s                     

stdout:
2023-03-07T18:57:54.280000Z TestFramework (INFO): PRNG seed is: 6725125940728086953
2023-03-07T18:57:54.281000Z TestFramework (INFO): Initializing test directory /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97
2023-03-07T18:58:07.823000Z TestFramework (INFO): Prepare blocks without sending them to the node
2023-03-07T18:58:07.897000Z TestFramework (INFO): Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled
2023-03-07T18:59:48.100000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        test_function = lambda: self.is_connected
'''
2023-03-07T18:59:48.100000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
    self.run_test()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 77, in run_test
    peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 663, in add_outbound_p2p_connection
    p2p_conn.wait_for_connect()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 467, in wait_for_connect
    wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
  File "/home/ubuntu/ci_scratch/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 ''''
        test_function = lambda: self.is_connected
''' not true after 60.0 seconds
2023-03-07T18:59:58.119000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
'''
[node 0] Cleaning up leftover process


stderr:
Traceback (most recent call last):
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 164, in <module>
    P2PIBDStallingTest().main()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 157, in main
    exit_code = self.shutdown()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 309, in shutdown
    self.network_thread.close()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 603, in close
    wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
  File "/home/ubuntu/ci_scratch/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 ''''
        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
''' not true after 10.0 seconds
Task was destroyed but it is pending!
task: <Task pending name='Task-9' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/lib/python3.10/asyncio/selector_events.py:193>>
/usr/lib/python3.10/asyncio/base_events.py:671: RuntimeWarning: coroutine 'BaseSelectorEventLoop._accept_connection2' was never awaited


Combine the logs and print the last 99999999 lines ...

============
Combined log for /home/ubuntu/ci_scratch/ci/scratch/test_runner//test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97:
============

 test  2023-03-07T18:57:54.280000Z TestFramework (INFO): PRNG seed is: 6725125940728086953 
 test  2023-03-07T18:57:54.280000Z TestFramework (DEBUG): Setting up network thread 
 test  2023-03-07T18:57:54.281000Z TestFramework (INFO): Initializing test directory /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97 
 test  2023-03-07T18:57:54.282000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 node0 2023-03-07T18:57:58.877542Z [init] [init/common.cpp:149] [LogPackageVersion] Bitcoin Core version v24.99.0-86bacd75e76e (release build) 
 node0 2023-03-07T18:57:58.919600Z [init] [init.cpp:680] [InitParameterInteraction] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 node0 2023-03-07T18:58:00.668764Z [init] [kernel/context.cpp:21] [Context] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 node0 2023-03-07T18:58:00.672072Z [init] [random.cpp:99] [ReportHardwareRand] Using RdSeed as an additional entropy source 
 node0 2023-03-07T18:58:00.673155Z [init] [random.cpp:102] [ReportHardwareRand] Using RdRand as an additional entropy source 
 node0 2023-03-07T18:58:01.412897Z [init] [init/common.cpp:120] [StartLogging] Default data directory /home/nonroot/.bitcoin 
 node0 2023-03-07T18:58:01.415276Z [init] [init/common.cpp:121] [StartLogging] Using data directory /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest 
 node0 2023-03-07T18:58:01.417278Z [init] [init/common.cpp:126] [StartLogging] Config file: /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/bitcoin.conf 
 node0 2023-03-07T18:58:01.426618Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: regtest="1" 
 node0 2023-03-07T18:58:01.429110Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 node0 2023-03-07T18:58:01.429590Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 node0 2023-03-07T18:58:01.430056Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 node0 2023-03-07T18:58:01.430532Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 node0 2023-03-07T18:58:01.431006Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 node0 2023-03-07T18:58:01.431457Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 node0 2023-03-07T18:58:01.431933Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 node0 2023-03-07T18:58:01.432386Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 node0 2023-03-07T18:58:01.432837Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 node0 2023-03-07T18:58:01.433304Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999" 
 node0 2023-03-07T18:58:01.433795Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] port="12164" 
 node0 2023-03-07T18:58:01.434310Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 node0 2023-03-07T18:58:01.434842Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1" 
 node0 2023-03-07T18:58:01.435364Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcport="17164" 
 node0 2023-03-07T18:58:01.435879Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] server="1" 
 node0 2023-03-07T18:58:01.436374Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 node0 2023-03-07T18:58:01.436854Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 node0 2023-03-07T18:58:01.437302Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] upnp="0" 
 node0 2023-03-07T18:58:01.438868Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: datadir="/home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0" 
 node0 2023-03-07T18:58:01.439366Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debug="" 
 node0 2023-03-07T18:58:01.439860Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 node0 2023-03-07T18:58:01.440342Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 node0 2023-03-07T18:58:01.440820Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="rand" 
 node0 2023-03-07T18:58:01.441272Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: disablewallet="" 
 node0 2023-03-07T18:58:01.441774Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: loglevel="trace" 
 node0 2023-03-07T18:58:01.442265Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 node0 2023-03-07T18:58:01.442769Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logthreadnames="" 
 node0 2023-03-07T18:58:01.443248Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logtimemicros="" 
 node0 2023-03-07T18:58:01.443766Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 node0 2023-03-07T18:58:01.447151Z [init] [init.cpp:1124] [AppInitMain] Using at most 125 automatic connections (1048564 file descriptors available) 
 node0 2023-03-07T18:58:01.720629Z [init] [script/sigcache.cpp:103] [InitSignatureCache] Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements 
 node0 2023-03-07T18:58:01.955825Z [init] [validation.cpp:1733] [InitScriptExecutionCache] Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements 
 node0 2023-03-07T18:58:01.958846Z [init] [init.cpp:1156] [AppInitMain] Script verification uses 15 additional threads 
 node0 2023-03-07T18:58:02.389437Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start 
 node0 2023-03-07T18:58:02.437801Z [init] [wallet/init.cpp:132] [Construct] Wallet disabled! 
 node0 2023-03-07T18:58:04.348117Z [init] [httpserver.cpp:192] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 node0 2023-03-07T18:58:04.397260Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 
 node0 2023-03-07T18:58:04.413197Z [init] [httpserver.cpp:378] [libevent_log_cb] [libevent:warning] getaddrinfo: address family for nodename not supported 
 node0 2023-03-07T18:58:04.415194Z [init] [httpserver.cpp:346] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 failed. 
 node0 2023-03-07T18:58:04.416023Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 17164 
 node0 2023-03-07T18:58:04.440550Z [init] [httpserver.cpp:417] [InitHTTPServer] [http] Initialized HTTP server 
 node0 2023-03-07T18:58:04.443111Z [init] [httpserver.cpp:419] [InitHTTPServer] [http] creating work queue of depth 16 
 node0 2023-03-07T18:58:04.459267Z [init] [rpc/server.cpp:289] [StartRPC] [rpc] Starting RPC 
 node0 2023-03-07T18:58:04.534013Z [init] [httprpc.cpp:296] [StartHTTPRPC] [rpc] Starting HTTP RPC server 
 node0 2023-03-07T18:58:04.536091Z [init] [httprpc.cpp:245] [InitRPCAuthentication] Using random cookie authentication. 
 node0 2023-03-07T18:58:04.544464Z [init] [rpc/request.cpp:106] [GenerateAuthCookie] Generated RPC authentication cookie /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/.cookie 
 node0 2023-03-07T18:58:04.554112Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1) 
 node0 2023-03-07T18:58:04.571066Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0) 
 node0 2023-03-07T18:58:04.582184Z [init] [httpserver.cpp:441] [StartHTTPServer] [http] Starting HTTP server 
 node0 2023-03-07T18:58:04.583679Z [init] [httpserver.cpp:443] [StartHTTPServer] [http] starting 4 worker threads 
 node0 2023-03-07T18:58:04.722619Z [init] [init.cpp:1241] [AppInitMain] Using /16 prefix for IP bucketing 
 node0 2023-03-07T18:58:04.755641Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading P2P addresses… 
 node0 2023-03-07T18:58:04.793085Z [http] [httpserver.cpp:304] [ThreadHTTP] [http] Entering http event loop 
 node0 2023-03-07T18:58:04.845359Z [init] [addrdb.cpp:197] [LoadAddrman] Creating peers.dat because the file was not found ("/home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/peers.dat") 
 node0 2023-03-07T18:58:04.948138Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading banlist… 
 node0 2023-03-07T18:58:05.018579Z [init] [banman.cpp:41] [LoadBanlist] Recreating the banlist database 
 node0 2023-03-07T18:58:05.050583Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43846 
 node0 2023-03-07T18:58:05.082656Z [init] [banman.cpp:67] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  50ms 
 node0 2023-03-07T18:58:05.117763Z [init] [net.cpp:1561] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false 
 node0 2023-03-07T18:58:05.206330Z [init] [net.cpp:2236] [SetNetworkActive] SetNetworkActive: true 
 node0 2023-03-07T18:58:05.319634Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-07T18:58:05.342400Z [init] [policy/fees.cpp:551] [CBlockPolicyEstimator] Failed to read fee estimates from /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/fee_estimates.dat. Continue anyway. 
 node0 2023-03-07T18:58:05.435100Z [init] [init.cpp:1456] [AppInitMain] Cache configuration: 
 node0 2023-03-07T18:58:05.443491Z [init] [init.cpp:1457] [AppInitMain] * Using 2.0 MiB for block index database 
 node0 2023-03-07T18:58:05.459910Z [init] [init.cpp:1465] [AppInitMain] * Using 8.0 MiB for chain state database 
 node0 2023-03-07T18:58:05.480090Z [init] [init.cpp:1483] [AppInitMain] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 
 node0 2023-03-07T18:58:05.568239Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading block index… 
 node0 2023-03-07T18:58:05.575716Z [init] [node/chainstate.cpp:41] [LoadChainstate] Validating signatures for all blocks. 
 node0 2023-03-07T18:58:05.580071Z [init] [node/chainstate.cpp:43] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 node0 2023-03-07T18:58:05.623991Z [init] [dbwrapper.cpp:150] [CDBWrapper] Opening LevelDB in /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/blocks/index 
 node0 2023-03-07T18:58:05.718871Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43852 
 node0 2023-03-07T18:58:05.756214Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-07T18:58:05.819815Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
 node0 2023-03-07T18:58:05.860801Z [init] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/blocks/index: 0000000000000000 
 node0 2023-03-07T18:58:05.929484Z [init] [node/blockstorage.cpp:331] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
 node0 2023-03-07T18:58:05.940571Z [init] [node/blockstorage.cpp:335] [LoadBlockIndexDB] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=0, size=0, heights=0...0, time=1970-01-01...1970-01-01) 
 node0 2023-03-07T18:58:05.943096Z [init] [node/blockstorage.cpp:346] [LoadBlockIndexDB] Checking all blk files are present... 
 node0 2023-03-07T18:58:05.955227Z [init] [validation.cpp:4432] [LoadBlockIndex] Initializing databases... 
 node0 2023-03-07T18:58:05.997829Z [init] [flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x1000000 in blk00000.dat 
 node0 2023-03-07T18:58:06.116950Z [init] [node/chainstate.cpp:124] [LoadChainstate] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
 node0 2023-03-07T18:58:06.122862Z [init] [dbwrapper.cpp:150] [CDBWrapper] Opening LevelDB in /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/chainstate 
 node0 2023-03-07T18:58:06.125199Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43860 
 node0 2023-03-07T18:58:06.127331Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-07T18:58:06.136827Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
 node0 2023-03-07T18:58:06.179639Z [init] [dbwrapper.cpp:180] [CDBWrapper] Wrote new obfuscate key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/chainstate: bf7f59c89c91aab9 
 node0 2023-03-07T18:58:06.180604Z [init] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/chainstate: bf7f59c89c91aab9 
 node0 2023-03-07T18:58:06.243967Z [init] [validation.cpp:5316] [MaybeRebalanceCaches] [snapshot] allocating all cache to the IBD chainstate 
 node0 2023-03-07T18:58:06.269754Z [init] [dbwrapper.cpp:150] [CDBWrapper] Opening LevelDB in /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/chainstate 
 node0 2023-03-07T18:58:06.455878Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43866 
 node0 2023-03-07T18:58:06.457951Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-07T18:58:06.471165Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
 node0 2023-03-07T18:58:06.523245Z [init] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97/node0/regtest/chainstate: bf7f59c89c91aab9 
 node0 2023-03-07T18:58:06.529230Z [init] [validation.cpp:4859] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinsdb cache to 8.0 MiB 
 node0 2023-03-07T18:58:06.530749Z [init] [validation.cpp:4861] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinstip cache to 440.0 MiB 
 node0 2023-03-07T18:58:06.547340Z [init] [noui.cpp:56] [noui_InitMessage] init message: Verifying blocks… 
 node0 2023-03-07T18:58:06.556832Z [init] [init.cpp:1526] [AppInitMain]  block index             986ms 
 node0 2023-03-07T18:58:06.672492Z [init] [init.cpp:1615] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
 node0 2023-03-07T18:58:06.728696Z [loadblk] [util/thread.cpp:20] [TraceThread] loadblk thread start 
 node0 2023-03-07T18:58:06.856607Z [loadblk] [validation.cpp:2821] [ConnectTip] [bench]   - Load block from disk: 68.33ms [0.07s (infms/blk)] 
 node0 2023-03-07T18:58:06.898101Z [loadblk] [validationinterface.cpp:255] [BlockChecked] [validation] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
 node0 2023-03-07T18:58:06.914070Z [loadblk] [validation.cpp:2837] [ConnectTip] [bench]   - Connect total: 65.43ms [0.07s (65.43ms/blk)] 
 node0 2023-03-07T18:58:06.919434Z [loadblk] [validation.cpp:2846] [ConnectTip] [bench]   - Flush: 5.47ms [0.01s (5.47ms/blk)] 
 node0 2023-03-07T18:58:06.921838Z [loadblk] [validation.cpp:2856] [ConnectTip] [bench]   - Writing chainstate: 2.43ms [0.00s (2.43ms/blk)] 
 node0 2023-03-07T18:58:06.967740Z [loadblk] [validation.cpp:2616] [UpdateTipLog] UpdateTip: new best=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 version=0x00000001 log2_work=1.000000 tx=1 date='2011-02-02T23:16:42Z' progress=1.000000 cache=0.0MiB(0txo) 
 node0 2023-03-07T18:58:06.970412Z [loadblk] [validation.cpp:2872] [ConnectTip] [bench]   - Connect postprocess: 48.43ms [0.05s (48.43ms/blk)] 
 node0 2023-03-07T18:58:06.971974Z [loadblk] [validation.cpp:2876] [ConnectTip] [bench] - Connect block: 190.09ms [0.19s (190.09ms/blk)] 
 node0 2023-03-07T18:58:06.995432Z [loadblk] [txmempool.cpp:644] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
 node0 2023-03-07T18:58:07.018881Z [loadblk] [validationinterface.cpp:232] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2023-03-07T18:58:07.035274Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43882 
 node0 2023-03-07T18:58:07.045922Z [loadblk] [validationinterface.cpp:204] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2023-03-07T18:58:07.058721Z [scheduler] [validationinterface.cpp:232] [operator()] [validation] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2023-03-07T18:58:07.108662Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-07T18:58:07.185730Z [loadblk] [kernel/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file from disk. Continuing anyway. 
 node0 2023-03-07T18:58:07.192367Z [loadblk] [util/thread.cpp:22] [TraceThread] loadblk thread exit 
 node0 2023-03-07T18:58:07.199416Z [init] [init.cpp:1702] [AppInitMain] block tree size = 1 
 node0 2023-03-07T18:58:07.201669Z [init] [init.cpp:1714] [AppInitMain] nBestHeight = 0 
 node0 2023-03-07T18:58:07.265546Z [init] [net.cpp:2169] [BindListenPort] Bound to 127.0.0.1:12164 
 node0 2023-03-07T18:58:07.301398Z [init] [net.cpp:2166] [BindListenPort] [net:error] Unable to bind to 127.0.0.1:18445 on this computer. Bitcoin Core is probably already running. 
 node0 2023-03-07T18:58:07.305861Z [init] [noui.cpp:56] [noui_InitMessage] init message: Starting network threads… 
 node0 2023-03-07T18:58:07.343357Z [init] [net.cpp:2375] [Start] DNS seeding disabled 
 node0 2023-03-07T18:58:07.407367Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
 node0 2023-03-07T18:58:07.436083Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
 node0 2023-03-07T18:58:07.491320Z [scheduler] [validationinterface.cpp:204] [operator()] [validation] UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2023-03-07T18:58:07.497174Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
 node0 2023-03-07T18:58:07.497699Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
 node0 2023-03-07T18:58:07.525351Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.560667Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-07T18:58:07.611103Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.613064Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 test  2023-03-07T18:58:07.663000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node0 2023-03-07T18:58:07.665548Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.667926Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2023-03-07T18:58:07.675690Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.677699Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2023-03-07T18:58:07.701895Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.703867Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 node0 2023-03-07T18:58:07.760321Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.762318Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2023-03-07T18:58:07.765722Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.767559Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2023-03-07T18:58:07.770690Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.773406Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 test  2023-03-07T18:58:07.823000Z TestFramework (INFO): Prepare blocks without sending them to the node 
 test  2023-03-07T18:58:07.897000Z TestFramework (INFO): Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled 
 test  2023-03-07T18:58:07.897000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 1 
 test  2023-03-07T18:58:07.897000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12175 should be started 
 test  2023-03-07T18:58:07.897000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12175 outbound-full-relay 
 node0 2023-03-07T18:58:07.899327Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:07.901557Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-07T18:58:07.920812Z [httpworker.2] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12175 lastseen=0.0hrs 
 node0 2023-03-07T18:58:08.046809Z [httpworker.2] [net.cpp:2803] [CNode] [net] Added connection peer=0 
 node0 2023-03-07T18:58:08.144873Z [httpworker.2] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=0 
 node0 2023-03-07T18:58:08.177996Z [httpworker.2] [net_processing.cpp:1402] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=0 
 test  2023-03-07T18:58:08.191000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_version(nVersion=70016 nServices=9 nTime=Tue Mar  7 18:58:07 2023 addrTo=CAddress(nServices=1 net=IPv4 addr=0 port=0) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xC7C2CBF1CA426056 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_version(nVersion=70016 nServices=1033 nTime=Tue Mar  7 18:58:08 2023 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x19140C8041D1AB3A strSubVer=/Satoshi:24.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
 node0 2023-03-07T18:58:08.284544Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=0 
 node0 2023-03-07T18:58:08.307101Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=0 
 test  2023-03-07T18:58:08.308000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
 node0 2023-03-07T18:58:08.308796Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=0 
 test  2023-03-07T18:58:08.309000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
 node0 2023-03-07T18:58:08.328742Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=0 
 test  2023-03-07T18:58:08.330000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
 node0 2023-03-07T18:58:08.344965Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=0 
 test  2023-03-07T18:58:08.345000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
 test  2023-03-07T18:58:08.348000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
 node0 2023-03-07T18:58:08.353109Z [msghand] [net_processing.cpp:3366] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=0.0.0.0:0, txrelay=1, peer=0 
 node0 2023-03-07T18:58:08.385242Z [msghand] [timedata.cpp:57] [AddTimeData] [net] added time data, samples 2, offset -1 (+0 minutes) 
 node0 2023-03-07T18:58:08.395502Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=0 
 node0 2023-03-07T18:58:08.398039Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=0 
 node0 2023-03-07T18:58:08.403265Z [msghand] [net_processing.cpp:3409] [ProcessMessage] New outbound peer connected: version: 70016, blocks=-1, peer=0 (outbound-full-relay) 
 node0 2023-03-07T18:58:08.407199Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=0 
 test  2023-03-07T18:58:08.408000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
 test  2023-03-07T18:58:08.422000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=29efaad9ba235612) 
 node0 2023-03-07T18:58:08.422053Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=0 
 test  2023-03-07T18:58:08.423000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=29efaad9ba235612) 
 node0 2023-03-07T18:58:08.463141Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getheaders (69 bytes) peer=0 
 test  2023-03-07T18:58:08.464000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getheaders(locator=CBlockLocator(vHave=[7041830694386478471858881810674310864173988660927928131397671070347943617030]), stop=0000000000000000000000000000000000000000000000000000000000000000) 
 node0 2023-03-07T18:58:08.468601Z [msghand] [net_processing.cpp:5428] [SendMessages] [net] initial getheaders (0) to peer=0 (startheight:-1) 
 node0 2023-03-07T18:58:08.578692Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=0 
 test  2023-03-07T18:58:08.580000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
 node0 2023-03-07T18:58:08.582867Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=0 
 node0 2023-03-07T18:58:08.587656Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=0 
 node0 2023-03-07T18:58:08.592392Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=0 
 node0 2023-03-07T18:58:08.593933Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=0 
 test  2023-03-07T18:58:08.594000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
 node0 2023-03-07T18:58:08.596070Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=0 
 test  2023-03-07T18:58:08.615000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_headers(headers=[CBlockHeader(nVersion=4 hashPrevBlock=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 hashMerkleRoot=4a74dde0b97a8704f2aed3db8fcf4f9dc4b52bf99478c2ccd21a6ccc3d8c327f nTime=Wed Feb  2 23:16:43 2011 nBits=207fffff nNonce=00000000), CBlockHeader(nVersion=4 hashPrevBlock=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Wed Feb  2 23:16:44 2011 nBits=207fffff nNo... (msg truncated) 
 test  2023-03-07T18:58:08.615000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 2 
 test  2023-03-07T18:58:08.615000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12174 should be started 
 test  2023-03-07T18:58:08.615000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12174 outbound-full-relay 
 node0 2023-03-07T18:58:08.683438Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:08.684640Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=0 
 node0 2023-03-07T18:58:33.760456Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-07T18:58:39.157807Z [httpworker.1] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12174 lastseen=0.0hrs 
 node0 2023-03-07T18:58:46.835711Z [msghand] [validation.cpp:3832] [ProcessNewBlockHeaders] Synchronizing blockheaders, height: 1024 (~0.16%) 
 node0 2023-03-07T18:58:46.841966Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=0 from eviction 
 node0 2023-03-07T18:58:46.854538Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=0 
 node0 2023-03-07T18:58:46.857799Z [httpworker.1] [net.cpp:2803] [CNode] [net] Added connection peer=1 
 node0 2023-03-07T18:58:46.908586Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 (1) peer=0 
 node0 2023-03-07T18:58:46.913399Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 (2) peer=0 
 node0 2023-03-07T18:58:46.915028Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e (3) peer=0 
 node0 2023-03-07T18:58:46.916177Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 (4) peer=0 
 node0 2023-03-07T18:58:46.916813Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba (5) peer=0 
 node0 2023-03-07T18:58:46.917881Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a (6) peer=0 
 node0 2023-03-07T18:58:46.918506Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 (7) peer=0 
 node0 2023-03-07T18:58:46.919101Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 (8) peer=0 
 node0 2023-03-07T18:58:46.919726Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b (9) peer=0 
 node0 2023-03-07T18:58:46.920318Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 (10) peer=0 
 node0 2023-03-07T18:58:46.920922Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 (11) peer=0 
 node0 2023-03-07T18:58:46.921525Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 5085f9b6a36365c466b6d84c96e74d7e135b245909bf37d2dc3169ae3fd8a358 (12) peer=0 
 node0 2023-03-07T18:58:46.922130Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 7c7867082cd45356564ebb64ba8004c756d694015b9f13ecd2e4161f2083e041 (13) peer=0 
 node0 2023-03-07T18:58:46.922749Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0db9883db92373bdb4c76b364dd8f884cef440ce7a199671e9d8772e4f51ec9e (14) peer=0 
 node0 2023-03-07T18:58:46.923344Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3efdfa1d6b4515648862589e3887ee60471334ce1b816af8ab4ef7319742d81e (15) peer=0 
 node0 2023-03-07T18:58:46.923940Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0b71784b174e34d19f54b019952d9437840aa0eb458132ccb8cf288d744bb853 (16) peer=0 
 node0 2023-03-07T18:58:46.932237Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (577 bytes) peer=0 
 node0 2023-03-07T18:58:46.938497Z [httpworker.1] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=1 
 node0 2023-03-07T18:58:46.939647Z [httpworker.1] [net_processing.cpp:1402] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=1 
 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendheaders() 
 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52), CInv(type=WitnessBlock hash=734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419), CInv(type=WitnessBlock hash=47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e), CInv(type=WitnessBlock hash=41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640), CInv(type=WitnessBlock hash=2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba), CInv(typ... (msg truncated) 
 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Wed Feb  2 23:16:44 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5251 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 hashMerkleRoot=3cc39162ed78b92f16a527306e356c6f2a7a5bc5f0543ee61901eb11117b6819 nTime=Wed Feb  2 23:16:45 2011 nBits=207fffff nNonce=00000006 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5351 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e hashMerkleRoot=b0e25423ef7d0d0f9f06a999dd923cb8fc8f032f01b0c13a7ebcb490a1769729 nTime=Wed Feb  2 23:16:46 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5451 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 hashMerkleRoot=868655d7c673cdc273402666bca76b767c1bf960fdaffbae33a1c4affd3b8a09 nTime=Wed Feb  2 23:16:47 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5551 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba hashMerkleRoot=63345f84104c76f0c62f6bc77f3bddc3bc2a87055bc9fbe0206315b79b9b0d29 nTime=Wed Feb  2 23:16:48 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5651 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a hashMerkleRoot=fdd8ed93eb95c922d03ed1b9f74d5f1749eccfb082bc4f8ecc5e9b002f7ba695 nTime=Wed Feb  2 23:16:49 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5751 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 hashMerkleRoot=017c3a811282fe9659f62cf6274d0135feeca915f9a999b01f55cb658858ec9c nTime=Wed Feb  2 23:16:50 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5851 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 hashMerkleRoot=77ce2fe03d1d6819ba6032f45a105f11ed0ea8f106000813ab36c68126bee3c6 nTime=Wed Feb  2 23:16:51 2011 nBits=207fffff nNonce=00000003 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5951 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b hashMerkleRoot=2dc01a6a03fd98d2d88afe9c12bc95f0acaaf420d4c91fede68860ded5324a2f nTime=Wed Feb  2 23:16:52 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5a51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 hashMerkleRoot=7ae9a091c932d6e20037b21e6e8d221affdaf763bdc1c88f29987754afebd7d0 nTime=Wed Feb  2 23:16:53 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5b51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 hashMerkleRoot=b0ad1f8a76a371c570a02fd4ad99f51839cb9cb401826557b696fc9389ce66e5 nTime=Wed Feb  2 23:16:54 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5c51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=5085f9b6a36365c466b6d84c96e74d7e135b245909bf37d2dc3169ae3fd8a358 hashMerkleRoot=cdd4898e222054dcfa42fe2d358406bd60167a6d2b4d6aeff7496a33017bf966 nTime=Wed Feb  2 23:16:55 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5d51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=7c7867082cd45356564ebb64ba8004c756d694015b9f13ecd2e4161f2083e041 hashMerkleRoot=198cdae5645abffe14027a48f5d11991c2bc1aeece45670a480d8dd1a9baf749 nTime=Wed Feb  2 23:16:56 2011 nBits=207fffff nNonce=00000003 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5e51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.944000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0db9883db92373bdb4c76b364dd8f884cef440ce7a199671e9d8772e4f51ec9e hashMerkleRoot=ea318ea26390c9f8d1965ad210686792c2272e767989104413d121a33d754f41 nTime=Wed Feb  2 23:16:57 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5f51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3efdfa1d6b4515648862589e3887ee60471334ce1b816af8ab4ef7319742d81e hashMerkleRoot=bff3e88ce8c27200aaa6eef850b0f3e4f8f5b149ef6b75c50014066b48d2ec6c nTime=Wed Feb  2 23:16:58 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=6051 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_version(nVersion=70016 nServices=9 nTime=Tue Mar  7 18:58:08 2023 addrTo=CAddress(nServices=1 net=IPv4 addr=0 port=0) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x7480DFF57A5E906D strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_version(nVersion=70016 nServices=1033 nTime=Tue Mar  7 18:58:46 2023 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x5BFA1948B1175AE9 strSubVer=/Satoshi:24.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
 node0 2023-03-07T18:58:46.955692Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T18:58:46.983249Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 peer=0 
 node0 2023-03-07T18:58:47.206395Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364 (17) peer=0 
 node0 2023-03-07T18:58:47.208013Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-07T18:58:47.209000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364)]) 
 test  2023-03-07T18:58:47.209000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0b71784b174e34d19f54b019952d9437840aa0eb458132ccb8cf288d744bb853 hashMerkleRoot=e38415c928ce45c0ddc5953dae43e2141e829495004310deab10956a3d0b9ca8 nTime=Wed Feb  2 23:16:59 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0111 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T18:58:47.210079Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=1 
 node0 2023-03-07T18:58:47.211209Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1 
 test  2023-03-07T18:58:47.213000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
 node0 2023-03-07T18:58:47.213557Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1 
 test  2023-03-07T18:58:47.214000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
 node0 2023-03-07T18:58:47.217932Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=1 
 test  2023-03-07T18:58:47.218000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
 node0 2023-03-07T18:58:47.219676Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=1 
 test  2023-03-07T18:58:47.220000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
 node0 2023-03-07T18:58:47.220892Z [msghand] [net_processing.cpp:3366] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=0.0.0.0:0, txrelay=1, peer=1 
 node0 2023-03-07T18:58:47.231454Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 test  2023-03-07T18:58:47.232000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
 node0 2023-03-07T18:58:47.232798Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e peer=0 
 node0 2023-03-07T18:58:47.392314Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0 (18) peer=0 
 node0 2023-03-07T18:58:47.393081Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-07T18:58:47.394000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0)]) 
 test  2023-03-07T18:58:47.394000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364 hashMerkleRoot=e61b5bdba523759dc7426f53e0b11afc2e2ac3358ab85fd441daee896d98e935 nTime=Wed Feb  2 23:17:00 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0112 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T18:58:47.395036Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T18:58:47.396325Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 peer=0 
 node0 2023-03-07T18:58:47.556421Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b (19) peer=0 
 node0 2023-03-07T18:58:47.557962Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-07T18:58:47.558000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b)]) 
 test  2023-03-07T18:58:47.559000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0 hashMerkleRoot=5c81c9994bb73d9bc3e1f621f55ea39b0dae38278d0f41144de2b4e12518b82f nTime=Wed Feb  2 23:17:01 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0113 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T18:58:47.559328Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1 
 node0 2023-03-07T18:58:47.560703Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=1 
 node0 2023-03-07T18:58:47.562214Z [msghand] [net_processing.cpp:3409] [ProcessMessage] New outbound peer connected: version: 70016, blocks=-1, peer=1 (outbound-full-relay) 
 node0 2023-03-07T18:58:47.562801Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1 
 test  2023-03-07T18:58:47.563000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
 test  2023-03-07T18:58:47.564000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=cc5de4d1af85f04c) 
 test  2023-03-07T18:58:47.564000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=cc5de4d1af85f04c) 
 node0 2023-03-07T18:58:47.564254Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=1 
 node0 2023-03-07T18:58:47.567248Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=1 
 test  2023-03-07T18:58:47.569000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
 node0 2023-03-07T18:58:47.569917Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T18:58:47.571210Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba peer=0 
 node0 2023-03-07T18:58:47.730576Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566 (20) peer=0 
 node0 2023-03-07T18:58:47.731335Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-07T18:58:47.732000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566)]) 
 test  2023-03-07T18:58:47.732000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b hashMerkleRoot=70b26d066fed597031248167043f37c1e62220d10f3a48d54545716e9f275f22 nTime=Wed Feb  2 23:17:02 2011 nBits=207fffff nNonce=00000005 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0114 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T18:58:47.733223Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T18:58:47.734613Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a peer=0 
 node0 2023-03-07T18:58:47.894775Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
 node0 2023-03-07T18:58:47.895530Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-07T18:58:47.897000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606)]) 
 test  2023-03-07T18:58:47.897000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566 hashMerkleRoot=88b88a2c16c9d33a7ae5fa5f728d52ce6d42ccb9733cba3699efc037c227184d nTime=Wed Feb  2 23:17:03 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0115 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T18:58:47.897709Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=1 
 node0 2023-03-07T18:58:47.898495Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=1 
 node0 2023-03-07T18:58:47.902386Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T18:58:47.903681Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 peer=0 
 node0 2023-03-07T18:58:48.062975Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695 (22) peer=0 
 node0 2023-03-07T18:58:48.063734Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-07T18:58:48.065000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695)]) 
 test  2023-03-07T18:58:48.065000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 hashMerkleRoot=4b2d553f063386720c17dc3606b84717f494fb242713d0f59e9b462960924831 nTime=Wed Feb  2 23:17:04 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0116 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T18:58:48.065945Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 node0 2023-03-07T18:58:48.066734Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=1 
 test  2023-03-07T18:58:48.067000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
 node0 2023-03-07T18:58:48.070071Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T18:58:48.071994Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 peer=0 
 test  2023-03-07T18:58:48.093000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_headers(headers=[CBlockHeader(nVersion=4 hashPrevBlock=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 hashMerkleRoot=4a74dde0b97a8704f2aed3db8fcf4f9dc4b52bf99478c2ccd21a6ccc3d8c327f nTime=Wed Feb  2 23:16:43 2011 nBits=207fffff nNonce=00000000), CBlockHeader(nVersion=4 hashPrevBlock=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Wed Feb  2 23:16:44 2011 nBits=207fffff nNo... (msg truncated) 
 test  2023-03-07T18:58:48.093000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 3 
 test  2023-03-07T18:58:48.094000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12173 should be started 
 test  2023-03-07T18:58:48.094000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
 node0 2023-03-07T18:58:48.240548Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:43890 
 node0 2023-03-07T18:58:48.322924Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 08aa76b207041d4ca67a570c816e7f577456fcdb435f8116cd929310a8be036b (23) peer=0 
 node0 2023-03-07T18:58:48.323684Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 node0 2023-03-07T18:58:48.326238Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-07T18:58:48.328168Z [httpworker.0] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12173 lastseen=0.0hrs 
 node0 2023-03-07T18:58:48.329268Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=1 
 node0 2023-03-07T18:58:48.331071Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
 node0 2023-03-07T18:59:36.109346Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=2 
 test  2023-03-07T18:59:48.100000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           test_function = lambda: self.is_connected
                                   '''
 test  2023-03-07T18:59:48.100000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
                                       self.run_test()
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 77, in run_test
                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 663, in add_outbound_p2p_connection
                                       p2p_conn.wait_for_connect()
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 467, in wait_for_connect
                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
                                     File "/home/ubuntu/ci_scratch/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 ''''
                                           test_function = lambda: self.is_connected
                                   ''' not true after 60.0 seconds
 test  2023-03-07T18:59:48.103000Z TestFramework (DEBUG): Closing down network thread 
 test  2023-03-07T18:59:58.119000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
                                   '''
 node0 2023-03-07T19:00:07.633394Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=1 from eviction 
 node0 2023-03-07T19:00:07.635479Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=1 
 node0 2023-03-07T19:00:07.638418Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 32d0a4daa0df30241959a213af52f872502e73b095ddbe5323a208b904a73cb1 (24) peer=1 
 node0 2023-03-07T19:00:07.639121Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 09f3aa3df2944b2ceeba47e792c6d96b41d724b390a052d320ca22d9e2de9012 (25) peer=1 
 node0 2023-03-07T19:00:07.639828Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3b754dfb708ce6b74d4955c29408e42bcf3a0e4ad466324ba8f14956f407ffea (26) peer=1 
 node0 2023-03-07T19:00:07.640492Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 75046beae1a2feaf24485e346fb1d33cbabf26f206e471ef37e3e7fdfefefed6 (27) peer=1 
 node0 2023-03-07T19:00:07.641143Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 164122b380be7b31386bba20ce51464289202b918cdff4714cc8cb582246322f (28) peer=1 
 node0 2023-03-07T19:00:07.641771Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 102cfea750c1bb27441ab8d9b2abceafc668adc73fac1daf9ca81f4cb0197100 (29) peer=1 
 node0 2023-03-07T19:00:07.642402Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 012e6ae5ac239038986efefbfbacabfe7e35f41f63ebac5ebab8125672e374bb (30) peer=1 
 node0 2023-03-07T19:00:07.643026Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 5e5053b392b2df297fcd3f6017c349fa1ca96ad55b455011ac799b103be031e6 (31) peer=1 
 node0 2023-03-07T19:00:07.643676Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 28ed8e55724939c57a82bd0dbc913d2341d116e59ca8252c4d6d9cbf02090296 (32) peer=1 
 node0 2023-03-07T19:00:07.644301Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 7e1208f27dec5a96694ee5ca803b723dfdc09cc9a19ea94131539f14c098ecd2 (33) peer=1 
 node0 2023-03-07T19:00:07.644915Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2041edbf200026cb6acc76934baad2fdb5d66b0bb039ee3492f6cf440c003c69 (34) peer=1 
 node0 2023-03-07T19:00:07.645529Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 721e244470287bf477524deb06cbc5a177ad514494584dfcc3a56ef289cf3804 (35) peer=1 
 node0 2023-03-07T19:00:07.646150Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0c73b90ebf04b40e3df140fcea633d2df7f0a6b42c9a3a79c372672a518e8d4f (36) peer=1 
 node0 2023-03-07T19:00:07.646803Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 76194c04ce42a14619061cd661823b0e278a05e3c1328248faf4875aa7ecc2bc (37) peer=1 
 node0 2023-03-07T19:00:07.647418Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 776f4c9d49066296f07e33989dc8b009ae039a98f531af0456973e963f78271d (38) peer=1 
 node0 2023-03-07T19:00:07.648038Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 4bb31266b2154fe7a748d067bb4105834dbbc300c7ba0caa408d080288b1f9e2 (39) peer=1 
 node0 2023-03-07T19:00:07.649667Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (577 bytes) peer=1 
 node0 2023-03-07T19:00:07.651723Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T19:00:07.653059Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b peer=0 
 node0 2023-03-07T19:00:07.814636Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6551539089fe92307bce623870921c1ff450de87039bd618d28d8aeb17ca677f (40) peer=0 
 node0 2023-03-07T19:00:07.816036Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 node0 2023-03-07T19:00:07.819371Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T19:00:07.829629Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 peer=0 
 node0 2023-03-07T19:00:07.923337Z [httpworker.0] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=2 
 node0 2023-03-07T19:00:08.011615Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 4e4ec0e940718b46978e8b83fa465ed9ea8db3dd1c45981f81e3b3f800e852a3 (41) peer=0 
 node0 2023-03-07T19:00:08.013471Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 node0 2023-03-07T19:00:08.018436Z [httpworker.0] [net_processing.cpp:1402] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=2 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=08aa76b207041d4ca67a570c816e7f577456fcdb435f8116cd929310a8be036b)]) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695 hashMerkleRoot=057a492cb69df3cf711bd39d7f3c8bcf03db0e09828cdaff4b8938505e4aefb9 nTime=Wed Feb  2 23:17:05 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0117 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=6551539089fe92307bce623870921c1ff450de87039bd618d28d8aeb17ca677f)]) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=4bb31266b2154fe7a748d067bb4105834dbbc300c7ba0caa408d080288b1f9e2 hashMerkleRoot=c0fe05b2ebc176a6762f166edcb01aa5970d8ce2da47370fd260ca187c8b5ea5 nTime=Wed Feb  2 23:17:22 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0128 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=4e4ec0e940718b46978e8b83fa465ed9ea8db3dd1c45981f81e3b3f800e852a3)]) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=6551539089fe92307bce623870921c1ff450de87039bd618d28d8aeb17ca677f hashMerkleRoot=65acb5233225c3c8fd08ef5639a04a8163775ebf92b733a426b009c4fbfcda8a nTime=Wed Feb  2 23:17:23 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0129 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendheaders() 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=32d0a4daa0df30241959a213af52f872502e73b095ddbe5323a208b904a73cb1), CInv(type=WitnessBlock hash=09f3aa3df2944b2ceeba47e792c6d96b41d724b390a052d320ca22d9e2de9012), CInv(type=WitnessBlock hash=3b754dfb708ce6b74d4955c29408e42bcf3a0e4ad466324ba8f14956f407ffea), CInv(type=WitnessBlock hash=75046beae1a2feaf24485e346fb1d33cbabf26f206e471ef37e3e7fdfefefed6), CInv(type=WitnessBlock hash=164122b380be7b31386bba20ce51464289202b918cdff4714cc8cb582246322f), CInv(typ... (msg truncated) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=08aa76b207041d4ca67a570c816e7f577456fcdb435f8116cd929310a8be036b hashMerkleRoot=7fd990bc174828c05dd32d8a829397bb656839d71e684a7fc3b7707a3db6eaee nTime=Wed Feb  2 23:17:06 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0118 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=32d0a4daa0df30241959a213af52f872502e73b095ddbe5323a208b904a73cb1 hashMerkleRoot=8a388712a9476960e580f518d6b7ac8d1ede25118b6be80ba50b89cdbc5933b6 nTime=Wed Feb  2 23:17:07 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0119 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=09f3aa3df2944b2ceeba47e792c6d96b41d724b390a052d320ca22d9e2de9012 hashMerkleRoot=2a1dd023e5ef24ea4855af24214d7dc8ee8db7700ad0055fc2de4e7108cd877d nTime=Wed Feb  2 23:17:08 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=011a nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3b754dfb708ce6b74d4955c29408e42bcf3a0e4ad466324ba8f14956f407ffea hashMerkleRoot=dc107f4f2f3169415b5025cac9689c754cc8dfc101f23cc65d47a1123bcd89d6 nTime=Wed Feb  2 23:17:09 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=011b nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=75046beae1a2feaf24485e346fb1d33cbabf26f206e471ef37e3e7fdfefefed6 hashMerkleRoot=3a9df7b1fe46f5edfd5207195cb732212f8982a6c71158e9993eb9c73cc34b95 nTime=Wed Feb  2 23:17:10 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=011c nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=164122b380be7b31386bba20ce51464289202b918cdff4714cc8cb582246322f hashMerkleRoot=416b862e955401a9b298b0d6f6297622a8ff460a2fb35221290dcd4551ce6105 nTime=Wed Feb  2 23:17:11 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=011d nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=102cfea750c1bb27441ab8d9b2abceafc668adc73fac1daf9ca81f4cb0197100 hashMerkleRoot=8f0515b7b1b4e915a3273b782b6a118b9c4ab32be15be5f0c0d792cc20f5e92e nTime=Wed Feb  2 23:17:12 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=011e nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=012e6ae5ac239038986efefbfbacabfe7e35f41f63ebac5ebab8125672e374bb hashMerkleRoot=364984ef3f47ed9e6d4f9618a7533e19005d20447e772db6a80d9a32c8c3a200 nTime=Wed Feb  2 23:17:13 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=011f nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=5e5053b392b2df297fcd3f6017c349fa1ca96ad55b455011ac799b103be031e6 hashMerkleRoot=cd887b8daec90f7abe3fadd8e50d531c357e7658910d1e9d9cb5af12049dccb6 nTime=Wed Feb  2 23:17:14 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0120 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=28ed8e55724939c57a82bd0dbc913d2341d116e59ca8252c4d6d9cbf02090296 hashMerkleRoot=b8263616dcb42c8c57a8b3dd9a8c3b8d9ccce4cffd2e204fa9b8eea7c1b24e62 nTime=Wed Feb  2 23:17:15 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0121 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=7e1208f27dec5a96694ee5ca803b723dfdc09cc9a19ea94131539f14c098ecd2 hashMerkleRoot=765f1e9e740405edc5204be993c67b8cf310e629a6b0a064e5288308d7d18f27 nTime=Wed Feb  2 23:17:16 2011 nBits=207fffff nNonce=00000003 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0122 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=2041edbf200026cb6acc76934baad2fdb5d66b0bb039ee3492f6cf440c003c69 hashMerkleRoot=3fcdc032636c882f6fb4f2c7279e2943d58517393d08c67c1b6aebe4bc121b9f nTime=Wed Feb  2 23:17:17 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0123 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=721e244470287bf477524deb06cbc5a177ad514494584dfcc3a56ef289cf3804 hashMerkleRoot=d277ce6bce558622c6ec18ca1e4437c8f825ba989b3df8f509bfcbbdc6a849a9 nTime=Wed Feb  2 23:17:18 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0124 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0c73b90ebf04b40e3df140fcea633d2df7f0a6b42c9a3a79c372672a518e8d4f hashMerkleRoot=76b4f87fd8ed64587f9ef2f3e551571cfa5cd369f6e4f8bd8fe0a7a1fc9f12a5 nTime=Wed Feb  2 23:17:19 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0125 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=76194c04ce42a14619061cd661823b0e278a05e3c1328248faf4875aa7ecc2bc hashMerkleRoot=66e78b1c11255584f9c939ac42faaaf904a70c1b4c67c536f85e6871ff58ddb9 nTime=Wed Feb  2 23:17:20 2011 nBits=207fffff nNonce=00000003 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0126 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-07T19:00:08.032000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=776f4c9d49066296f07e33989dc8b009ae039a98f531af0456973e963f78271d hashMerkleRoot=cd160730450ebca265bd447caa69f5f68e283f1d1011273dc214898a97805f34 nTime=Wed Feb  2 23:17:21 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0127 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-07T19:00:08.032744Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-07T19:00:08.036905Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 peer=0 
 node0 2023-03-07T19:00:08.152474Z [net] [net.cpp:1349] [SocketHandlerConnected] [net] socket closed for peer=0 
 node0 2023-03-07T19:00:08.155131Z [net] [net.cpp:589] [CloseSocketDisconnect] [net] disconnecting peer=0 
 node0 2023-03-07T19:00:08.328634Z [net] [net_processing.cpp:1538] [FinalizeNode] [net] Cleared nodestate for peer=0
  7. fanquake commented at 7:53 AM on March 8, 2023: member

    Log after running with #27221:

    ...............................................................................................                                                                                                           162/256 - p2p_ibd_stalling.py failed, Duration: 126 s

stdout:
2023-03-08T04:33:24.745000Z TestFramework (INFO): PRNG seed is: 3703385557670057473
2023-03-08T04:33:24.745000Z TestFramework (INFO): Initializing test directory /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97
2023-03-08T04:33:38.260000Z TestFramework (INFO): Prepare blocks without sending them to the node
2023-03-08T04:33:38.356000Z TestFramework (INFO): Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled
2023-03-08T04:35:17.908000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        test_function = lambda: self.is_connected
'''
2023-03-08T04:35:17.908000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
    self.run_test()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 77, in run_test
    peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 663, in add_outbound_p2p_connection
    p2p_conn.wait_for_connect()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 467, in wait_for_connect
    wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
  File "/home/ubuntu/ci_scratch/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 ''''
        test_function = lambda: self.is_connected
''' not true after 60.0 seconds
2023-03-08T04:35:27.925000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
'''
[node 0] Cleaning up leftover process


stderr:
Traceback (most recent call last):
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 164, in <module>
    P2PIBDStallingTest().main()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 155, in main
    exit_code = self.shutdown()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 310, in shutdown
    self.network_thread.close()
  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 603, in close
    wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
  File "/home/ubuntu/ci_scratch/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 ''''
        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
''' not true after 10.0 seconds
Task was destroyed but it is pending!
task: <Task pending name='Task-9' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/lib/python3.10/asyncio/selector_events.py:193>>
/usr/lib/python3.10/asyncio/base_events.py:671: RuntimeWarning: coroutine 'BaseSelectorEventLoop._accept_connection2' was never awaited


Combine the logs and print the last 99999999 lines ...

============
Combined log for /home/ubuntu/ci_scratch/ci/scratch/test_runner//test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97:
============

 test  2023-03-08T04:33:24.745000Z TestFramework (INFO): PRNG seed is: 3703385557670057473 
 test  2023-03-08T04:33:24.745000Z TestFramework (DEBUG): Setting up network thread 
 test  2023-03-08T04:33:24.745000Z TestFramework (INFO): Initializing test directory /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97 
 test  2023-03-08T04:33:24.746000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 node0 2023-03-08T04:33:29.336044Z [init] [init/common.cpp:149] [LogPackageVersion] Bitcoin Core version v24.99.0-fa27cf4cc7c2 (release build) 
 node0 2023-03-08T04:33:29.378276Z [init] [init.cpp:680] [InitParameterInteraction] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 node0 2023-03-08T04:33:31.125717Z [init] [kernel/context.cpp:21] [Context] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 node0 2023-03-08T04:33:31.129019Z [init] [random.cpp:99] [ReportHardwareRand] Using RdSeed as an additional entropy source 
 node0 2023-03-08T04:33:31.130115Z [init] [random.cpp:102] [ReportHardwareRand] Using RdRand as an additional entropy source 
 node0 2023-03-08T04:33:31.874529Z [init] [init/common.cpp:120] [StartLogging] Default data directory /home/nonroot/.bitcoin 
 node0 2023-03-08T04:33:31.876841Z [init] [init/common.cpp:121] [StartLogging] Using data directory /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest 
 node0 2023-03-08T04:33:31.878852Z [init] [init/common.cpp:126] [StartLogging] Config file: /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/bitcoin.conf 
 node0 2023-03-08T04:33:31.888176Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: regtest="1" 
 node0 2023-03-08T04:33:31.890686Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 node0 2023-03-08T04:33:31.891164Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 node0 2023-03-08T04:33:31.891638Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 node0 2023-03-08T04:33:31.892096Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 node0 2023-03-08T04:33:31.892570Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 node0 2023-03-08T04:33:31.893051Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 node0 2023-03-08T04:33:31.893525Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 node0 2023-03-08T04:33:31.893981Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 node0 2023-03-08T04:33:31.894434Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 node0 2023-03-08T04:33:31.894902Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999" 
 node0 2023-03-08T04:33:31.895388Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] port="12164" 
 node0 2023-03-08T04:33:31.895898Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 node0 2023-03-08T04:33:31.896426Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1" 
 node0 2023-03-08T04:33:31.896967Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcport="17164" 
 node0 2023-03-08T04:33:31.897491Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] server="1" 
 node0 2023-03-08T04:33:31.897990Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 node0 2023-03-08T04:33:31.898474Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 node0 2023-03-08T04:33:31.898928Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] upnp="0" 
 node0 2023-03-08T04:33:31.900483Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: datadir="/home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0" 
 node0 2023-03-08T04:33:31.901007Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debug="" 
 node0 2023-03-08T04:33:31.901512Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 node0 2023-03-08T04:33:31.902005Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 node0 2023-03-08T04:33:31.902489Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="rand" 
 node0 2023-03-08T04:33:31.902944Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: disablewallet="" 
 node0 2023-03-08T04:33:31.903443Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: loglevel="trace" 
 node0 2023-03-08T04:33:31.903945Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 node0 2023-03-08T04:33:31.904429Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logthreadnames="" 
 node0 2023-03-08T04:33:31.904911Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logtimemicros="" 
 node0 2023-03-08T04:33:31.905450Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 node0 2023-03-08T04:33:31.908828Z [init] [init.cpp:1124] [AppInitMain] Using at most 125 automatic connections (1048564 file descriptors available) 
 node0 2023-03-08T04:33:32.181859Z [init] [script/sigcache.cpp:103] [InitSignatureCache] Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements 
 node0 2023-03-08T04:33:32.414870Z [init] [validation.cpp:1733] [InitScriptExecutionCache] Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements 
 node0 2023-03-08T04:33:32.417869Z [init] [init.cpp:1156] [AppInitMain] Script verification uses 15 additional threads 
 node0 2023-03-08T04:33:32.847727Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start 
 node0 2023-03-08T04:33:32.891199Z [init] [wallet/init.cpp:132] [Construct] Wallet disabled! 
 node0 2023-03-08T04:33:34.823369Z [init] [httpserver.cpp:192] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 node0 2023-03-08T04:33:34.872094Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 
 node0 2023-03-08T04:33:34.887951Z [init] [httpserver.cpp:378] [libevent_log_cb] [libevent:warning] getaddrinfo: address family for nodename not supported 
 node0 2023-03-08T04:33:34.889937Z [init] [httpserver.cpp:346] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 failed. 
 node0 2023-03-08T04:33:34.890775Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 17164 
 node0 2023-03-08T04:33:34.915227Z [init] [httpserver.cpp:417] [InitHTTPServer] [http] Initialized HTTP server 
 node0 2023-03-08T04:33:34.917758Z [init] [httpserver.cpp:419] [InitHTTPServer] [http] creating work queue of depth 16 
 node0 2023-03-08T04:33:34.933872Z [init] [rpc/server.cpp:289] [StartRPC] [rpc] Starting RPC 
 node0 2023-03-08T04:33:35.008280Z [init] [httprpc.cpp:296] [StartHTTPRPC] [rpc] Starting HTTP RPC server 
 node0 2023-03-08T04:33:35.010321Z [init] [httprpc.cpp:245] [InitRPCAuthentication] Using random cookie authentication. 
 node0 2023-03-08T04:33:35.018571Z [init] [rpc/request.cpp:106] [GenerateAuthCookie] Generated RPC authentication cookie /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/.cookie 
 node0 2023-03-08T04:33:35.028162Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1) 
 node0 2023-03-08T04:33:35.045126Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0) 
 node0 2023-03-08T04:33:35.056233Z [init] [httpserver.cpp:441] [StartHTTPServer] [http] Starting HTTP server 
 node0 2023-03-08T04:33:35.057719Z [init] [httpserver.cpp:443] [StartHTTPServer] [http] starting 4 worker threads 
 node0 2023-03-08T04:33:35.171915Z [http] [httpserver.cpp:304] [ThreadHTTP] [http] Entering http event loop 
 node0 2023-03-08T04:33:35.202696Z [init] [init.cpp:1241] [AppInitMain] Using /16 prefix for IP bucketing 
 node0 2023-03-08T04:33:35.235458Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading P2P addresses… 
 node0 2023-03-08T04:33:35.323662Z [init] [addrdb.cpp:197] [LoadAddrman] Creating peers.dat because the file was not found ("/home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/peers.dat") 
 node0 2023-03-08T04:33:35.464321Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33774 
 node0 2023-03-08T04:33:35.511589Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading banlist… 
 node0 2023-03-08T04:33:35.580972Z [init] [banman.cpp:41] [LoadBanlist] Recreating the banlist database 
 node0 2023-03-08T04:33:35.607460Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-08T04:33:35.640888Z [init] [banman.cpp:67] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  46ms 
 node0 2023-03-08T04:33:35.696638Z [init] [net.cpp:1561] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false 
 node0 2023-03-08T04:33:35.720311Z [init] [net.cpp:2236] [SetNetworkActive] SetNetworkActive: true 
 node0 2023-03-08T04:33:35.845964Z [init] [policy/fees.cpp:551] [CBlockPolicyEstimator] Failed to read fee estimates from /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/fee_estimates.dat. Continue anyway. 
 node0 2023-03-08T04:33:35.910427Z [init] [init.cpp:1456] [AppInitMain] Cache configuration: 
 node0 2023-03-08T04:33:35.916431Z [init] [init.cpp:1457] [AppInitMain] * Using 2.0 MiB for block index database 
 node0 2023-03-08T04:33:35.920865Z [init] [init.cpp:1465] [AppInitMain] * Using 8.0 MiB for chain state database 
 node0 2023-03-08T04:33:35.940897Z [init] [init.cpp:1483] [AppInitMain] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 
 node0 2023-03-08T04:33:36.028711Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading block index… 
 node0 2023-03-08T04:33:36.036226Z [init] [node/chainstate.cpp:41] [LoadChainstate] Validating signatures for all blocks. 
 node0 2023-03-08T04:33:36.040953Z [init] [node/chainstate.cpp:43] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 node0 2023-03-08T04:33:36.092306Z [init] [dbwrapper.cpp:150] [CDBWrapper] Opening LevelDB in /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/blocks/index 
 node0 2023-03-08T04:33:36.131205Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33690 
 node0 2023-03-08T04:33:36.157676Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-08T04:33:36.280098Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
 node0 2023-03-08T04:33:36.321247Z [init] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/blocks/index: 0000000000000000 
 node0 2023-03-08T04:33:36.390249Z [init] [node/blockstorage.cpp:331] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
 node0 2023-03-08T04:33:36.401617Z [init] [node/blockstorage.cpp:335] [LoadBlockIndexDB] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=0, size=0, heights=0...0, time=1970-01-01...1970-01-01) 
 node0 2023-03-08T04:33:36.404146Z [init] [node/blockstorage.cpp:346] [LoadBlockIndexDB] Checking all blk files are present... 
 node0 2023-03-08T04:33:36.416288Z [init] [validation.cpp:4432] [LoadBlockIndex] Initializing databases... 
 node0 2023-03-08T04:33:36.459362Z [init] [flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x1000000 in blk00000.dat 
 node0 2023-03-08T04:33:36.579730Z [init] [node/chainstate.cpp:124] [LoadChainstate] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
 node0 2023-03-08T04:33:36.586472Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33700 
 node0 2023-03-08T04:33:36.587166Z [init] [dbwrapper.cpp:150] [CDBWrapper] Opening LevelDB in /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/chainstate 
 node0 2023-03-08T04:33:36.589283Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-08T04:33:36.602223Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
 node0 2023-03-08T04:33:36.645292Z [init] [dbwrapper.cpp:180] [CDBWrapper] Wrote new obfuscate key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/chainstate: d08a4a4d243b228d 
 node0 2023-03-08T04:33:36.646266Z [init] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/chainstate: d08a4a4d243b228d 
 node0 2023-03-08T04:33:36.709887Z [init] [validation.cpp:5316] [MaybeRebalanceCaches] [snapshot] allocating all cache to the IBD chainstate 
 node0 2023-03-08T04:33:36.735905Z [init] [dbwrapper.cpp:150] [CDBWrapper] Opening LevelDB in /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/chainstate 
 node0 2023-03-08T04:33:36.923551Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33702 
 node0 2023-03-08T04:33:36.925623Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-08T04:33:36.935842Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
 node0 2023-03-08T04:33:36.971149Z [init] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /home/ubuntu/ci_scratch/ci/scratch/test_runner/test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97/node0/regtest/chainstate: d08a4a4d243b228d 
 node0 2023-03-08T04:33:36.976133Z [init] [validation.cpp:4859] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinsdb cache to 8.0 MiB 
 node0 2023-03-08T04:33:36.977592Z [init] [validation.cpp:4861] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinstip cache to 440.0 MiB 
 node0 2023-03-08T04:33:36.994243Z [init] [noui.cpp:56] [noui_InitMessage] init message: Verifying blocks… 
 node0 2023-03-08T04:33:37.003735Z [init] [init.cpp:1526] [AppInitMain]  block index             973ms 
 node0 2023-03-08T04:33:37.120184Z [init] [init.cpp:1615] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
 node0 2023-03-08T04:33:37.176589Z [loadblk] [util/thread.cpp:20] [TraceThread] loadblk thread start 
 node0 2023-03-08T04:33:37.303188Z [loadblk] [validation.cpp:2821] [ConnectTip] [bench]   - Load block from disk: 67.60ms [0.07s (infms/blk)] 
 node0 2023-03-08T04:33:37.344681Z [loadblk] [validationinterface.cpp:255] [BlockChecked] [validation] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
 node0 2023-03-08T04:33:37.359966Z [loadblk] [validation.cpp:2837] [ConnectTip] [bench]   - Connect total: 64.73ms [0.06s (64.73ms/blk)] 
 node0 2023-03-08T04:33:37.365292Z [loadblk] [validation.cpp:2846] [ConnectTip] [bench]   - Flush: 5.42ms [0.01s (5.42ms/blk)] 
 node0 2023-03-08T04:33:37.367849Z [loadblk] [validation.cpp:2856] [ConnectTip] [bench]   - Writing chainstate: 2.58ms [0.00s (2.58ms/blk)] 
 node0 2023-03-08T04:33:37.413743Z [loadblk] [validation.cpp:2616] [UpdateTipLog] UpdateTip: new best=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 version=0x00000001 log2_work=1.000000 tx=1 date='2011-02-02T23:16:42Z' progress=1.000000 cache=0.0MiB(0txo) 
 node0 2023-03-08T04:33:37.417058Z [loadblk] [validation.cpp:2872] [ConnectTip] [bench]   - Connect postprocess: 49.07ms [0.05s (49.07ms/blk)] 
 node0 2023-03-08T04:33:37.418625Z [loadblk] [validation.cpp:2876] [ConnectTip] [bench] - Connect block: 189.40ms [0.19s (189.40ms/blk)] 
 node0 2023-03-08T04:33:37.442143Z [loadblk] [txmempool.cpp:644] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
 node0 2023-03-08T04:33:37.465583Z [loadblk] [validationinterface.cpp:232] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2023-03-08T04:33:37.489851Z [loadblk] [validationinterface.cpp:204] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2023-03-08T04:33:37.503977Z [scheduler] [validationinterface.cpp:232] [operator()] [validation] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2023-03-08T04:33:37.553336Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33704 
 node0 2023-03-08T04:33:37.627201Z [loadblk] [kernel/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file from disk. Continuing anyway. 
 node0 2023-03-08T04:33:37.631471Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-08T04:33:37.636774Z [init] [init.cpp:1702] [AppInitMain] block tree size = 1 
 node0 2023-03-08T04:33:37.639881Z [init] [init.cpp:1714] [AppInitMain] nBestHeight = 0 
 node0 2023-03-08T04:33:37.687986Z [init] [net.cpp:2169] [BindListenPort] Bound to 127.0.0.1:12164 
 node0 2023-03-08T04:33:37.724077Z [init] [net.cpp:2166] [BindListenPort] [net:error] Unable to bind to 127.0.0.1:18445 on this computer. Bitcoin Core is probably already running. 
 node0 2023-03-08T04:33:37.728781Z [init] [noui.cpp:56] [noui_InitMessage] init message: Starting network threads… 
 node0 2023-03-08T04:33:37.770143Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
 node0 2023-03-08T04:33:37.835001Z [scheduler] [validationinterface.cpp:204] [operator()] [validation] UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2023-03-08T04:33:37.843300Z [init] [net.cpp:2375] [Start] DNS seeding disabled 
 node0 2023-03-08T04:33:37.875528Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
 node0 2023-03-08T04:33:37.954508Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
 node0 2023-03-08T04:33:37.962532Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
 node0 2023-03-08T04:33:37.967210Z [loadblk] [util/thread.cpp:22] [TraceThread] loadblk thread exit 
 node0 2023-03-08T04:33:37.989769Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:37.992415Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2023-03-08T04:33:38.048242Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.050346Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 test  2023-03-08T04:33:38.100000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node0 2023-03-08T04:33:38.102038Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.104204Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2023-03-08T04:33:38.111188Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.113036Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 node0 2023-03-08T04:33:38.137257Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.139201Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 node0 2023-03-08T04:33:38.196438Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.198545Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2023-03-08T04:33:38.202696Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.204704Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2023-03-08T04:33:38.208081Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.210535Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 test  2023-03-08T04:33:38.260000Z TestFramework (INFO): Prepare blocks without sending them to the node 
 test  2023-03-08T04:33:38.356000Z TestFramework (INFO): Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled 
 test  2023-03-08T04:33:38.357000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 1 
 test  2023-03-08T04:33:38.357000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12175 should be started 
 test  2023-03-08T04:33:38.357000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12175 outbound-full-relay 
 node0 2023-03-08T04:33:38.359307Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:38.362283Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-08T04:33:38.390914Z [httpworker.0] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12175 lastseen=0.0hrs 
 node0 2023-03-08T04:33:38.522445Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=0 
 node0 2023-03-08T04:33:38.620249Z [httpworker.0] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=0 
 node0 2023-03-08T04:33:38.653609Z [httpworker.0] [net_processing.cpp:1402] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=0 
 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_version(nVersion=70016 nServices=9 nTime=Wed Mar  8 04:33:38 2023 addrTo=CAddress(nServices=1 net=IPv4 addr=0 port=0) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xE82603482BA7EAA3 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_version(nVersion=70016 nServices=1033 nTime=Wed Mar  8 04:33:38 2023 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x340DB705EBDB464C strSubVer=/Satoshi:24.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
 node0 2023-03-08T04:33:38.760350Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=0 
 node0 2023-03-08T04:33:38.782863Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=0 
 test  2023-03-08T04:33:38.783000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
 node0 2023-03-08T04:33:38.784558Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=0 
 test  2023-03-08T04:33:38.785000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
 node0 2023-03-08T04:33:38.804553Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=0 
 test  2023-03-08T04:33:38.805000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
 test  2023-03-08T04:33:38.808000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
 node0 2023-03-08T04:33:38.820743Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=0 
 test  2023-03-08T04:33:38.822000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
 node0 2023-03-08T04:33:38.829751Z [msghand] [net_processing.cpp:3366] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=0.0.0.0:0, txrelay=1, peer=0 
 node0 2023-03-08T04:33:38.860462Z [msghand] [timedata.cpp:57] [AddTimeData] [net] added time data, samples 2, offset +0 (+0 minutes) 
 node0 2023-03-08T04:33:38.869913Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=0 
 node0 2023-03-08T04:33:38.872434Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=0 
 node0 2023-03-08T04:33:38.877670Z [msghand] [net_processing.cpp:3409] [ProcessMessage] New outbound peer connected: version: 70016, blocks=-1, peer=0 (outbound-full-relay) 
 node0 2023-03-08T04:33:38.881594Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=0 
 test  2023-03-08T04:33:38.882000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
 node0 2023-03-08T04:33:38.896800Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=0 
 test  2023-03-08T04:33:38.897000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=1bb06eba4cb67ee6) 
 test  2023-03-08T04:33:38.897000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=1bb06eba4cb67ee6) 
 node0 2023-03-08T04:33:38.938124Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getheaders (69 bytes) peer=0 
 test  2023-03-08T04:33:38.939000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getheaders(locator=CBlockLocator(vHave=[7041830694386478471858881810674310864173988660927928131397671070347943617030]), stop=0000000000000000000000000000000000000000000000000000000000000000) 
 node0 2023-03-08T04:33:38.943550Z [msghand] [net_processing.cpp:5428] [SendMessages] [net] initial getheaders (0) to peer=0 (startheight:-1) 
 node0 2023-03-08T04:33:39.063559Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=0 
 test  2023-03-08T04:33:39.065000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
 node0 2023-03-08T04:33:39.069421Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=0 
 node0 2023-03-08T04:33:39.076589Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=0 
 node0 2023-03-08T04:33:39.082628Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=0 
 node0 2023-03-08T04:33:39.084173Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=0 
 test  2023-03-08T04:33:39.085000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
 node0 2023-03-08T04:33:39.086280Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=0 
 test  2023-03-08T04:33:39.125000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_headers(headers=[CBlockHeader(nVersion=4 hashPrevBlock=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 hashMerkleRoot=4a74dde0b97a8704f2aed3db8fcf4f9dc4b52bf99478c2ccd21a6ccc3d8c327f nTime=Wed Feb  2 23:16:43 2011 nBits=207fffff nNonce=00000000), CBlockHeader(nVersion=4 hashPrevBlock=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Wed Feb  2 23:16:44 2011 nBits=207fffff nNo... (msg truncated) 
 test  2023-03-08T04:33:39.125000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 2 
 test  2023-03-08T04:33:39.126000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12174 should be started 
 test  2023-03-08T04:33:39.126000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12174 outbound-full-relay 
 node0 2023-03-08T04:33:39.192664Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:33:39.193670Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=0 
 node0 2023-03-08T04:33:40.182417Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-08T04:33:48.873900Z [httpworker.3] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12174 lastseen=0.0hrs 
 node0 2023-03-08T04:34:16.953421Z [msghand] [validation.cpp:3832] [ProcessNewBlockHeaders] Synchronizing blockheaders, height: 1024 (~0.16%) 
 node0 2023-03-08T04:34:16.960677Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=0 from eviction 
 node0 2023-03-08T04:34:16.968677Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=0 
 node0 2023-03-08T04:34:16.975990Z [httpworker.3] [net.cpp:2803] [CNode] [net] Added connection peer=1 
 node0 2023-03-08T04:34:17.026473Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 (1) peer=0 
 node0 2023-03-08T04:34:17.031283Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 (2) peer=0 
 node0 2023-03-08T04:34:17.032878Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e (3) peer=0 
 node0 2023-03-08T04:34:17.034043Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 (4) peer=0 
 node0 2023-03-08T04:34:17.034682Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba (5) peer=0 
 node0 2023-03-08T04:34:17.035761Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a (6) peer=0 
 node0 2023-03-08T04:34:17.036375Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 (7) peer=0 
 node0 2023-03-08T04:34:17.036989Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 (8) peer=0 
 node0 2023-03-08T04:34:17.037626Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b (9) peer=0 
 node0 2023-03-08T04:34:17.038227Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 (10) peer=0 
 node0 2023-03-08T04:34:17.038829Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 (11) peer=0 
 node0 2023-03-08T04:34:17.039432Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 5085f9b6a36365c466b6d84c96e74d7e135b245909bf37d2dc3169ae3fd8a358 (12) peer=0 
 node0 2023-03-08T04:34:17.040050Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 7c7867082cd45356564ebb64ba8004c756d694015b9f13ecd2e4161f2083e041 (13) peer=0 
 node0 2023-03-08T04:34:17.040657Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0db9883db92373bdb4c76b364dd8f884cef440ce7a199671e9d8772e4f51ec9e (14) peer=0 
 node0 2023-03-08T04:34:17.041278Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3efdfa1d6b4515648862589e3887ee60471334ce1b816af8ab4ef7319742d81e (15) peer=0 
 node0 2023-03-08T04:34:17.041886Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0b71784b174e34d19f54b019952d9437840aa0eb458132ccb8cf288d744bb853 (16) peer=0 
 node0 2023-03-08T04:34:17.050154Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (577 bytes) peer=0 
 node0 2023-03-08T04:34:17.056789Z [httpworker.3] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=1 
 node0 2023-03-08T04:34:17.057911Z [httpworker.3] [net_processing.cpp:1402] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=1 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendheaders() 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52), CInv(type=WitnessBlock hash=734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419), CInv(type=WitnessBlock hash=47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e), CInv(type=WitnessBlock hash=41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640), CInv(type=WitnessBlock hash=2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba), CInv(typ... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Wed Feb  2 23:16:44 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5251 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 hashMerkleRoot=3cc39162ed78b92f16a527306e356c6f2a7a5bc5f0543ee61901eb11117b6819 nTime=Wed Feb  2 23:16:45 2011 nBits=207fffff nNonce=00000006 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5351 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e hashMerkleRoot=b0e25423ef7d0d0f9f06a999dd923cb8fc8f032f01b0c13a7ebcb490a1769729 nTime=Wed Feb  2 23:16:46 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5451 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 hashMerkleRoot=868655d7c673cdc273402666bca76b767c1bf960fdaffbae33a1c4affd3b8a09 nTime=Wed Feb  2 23:16:47 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5551 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba hashMerkleRoot=63345f84104c76f0c62f6bc77f3bddc3bc2a87055bc9fbe0206315b79b9b0d29 nTime=Wed Feb  2 23:16:48 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5651 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a hashMerkleRoot=fdd8ed93eb95c922d03ed1b9f74d5f1749eccfb082bc4f8ecc5e9b002f7ba695 nTime=Wed Feb  2 23:16:49 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5751 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 hashMerkleRoot=017c3a811282fe9659f62cf6274d0135feeca915f9a999b01f55cb658858ec9c nTime=Wed Feb  2 23:16:50 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5851 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 hashMerkleRoot=77ce2fe03d1d6819ba6032f45a105f11ed0ea8f106000813ab36c68126bee3c6 nTime=Wed Feb  2 23:16:51 2011 nBits=207fffff nNonce=00000003 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5951 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b hashMerkleRoot=2dc01a6a03fd98d2d88afe9c12bc95f0acaaf420d4c91fede68860ded5324a2f nTime=Wed Feb  2 23:16:52 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5a51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 hashMerkleRoot=7ae9a091c932d6e20037b21e6e8d221affdaf763bdc1c88f29987754afebd7d0 nTime=Wed Feb  2 23:16:53 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5b51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 hashMerkleRoot=b0ad1f8a76a371c570a02fd4ad99f51839cb9cb401826557b696fc9389ce66e5 nTime=Wed Feb  2 23:16:54 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5c51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=5085f9b6a36365c466b6d84c96e74d7e135b245909bf37d2dc3169ae3fd8a358 hashMerkleRoot=cdd4898e222054dcfa42fe2d358406bd60167a6d2b4d6aeff7496a33017bf966 nTime=Wed Feb  2 23:16:55 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5d51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=7c7867082cd45356564ebb64ba8004c756d694015b9f13ecd2e4161f2083e041 hashMerkleRoot=198cdae5645abffe14027a48f5d11991c2bc1aeece45670a480d8dd1a9baf749 nTime=Wed Feb  2 23:16:56 2011 nBits=207fffff nNonce=00000003 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5e51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0db9883db92373bdb4c76b364dd8f884cef440ce7a199671e9d8772e4f51ec9e hashMerkleRoot=ea318ea26390c9f8d1965ad210686792c2272e767989104413d121a33d754f41 nTime=Wed Feb  2 23:16:57 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5f51 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=3efdfa1d6b4515648862589e3887ee60471334ce1b816af8ab4ef7319742d81e hashMerkleRoot=bff3e88ce8c27200aaa6eef850b0f3e4f8f5b149ef6b75c50014066b48d2ec6c nTime=Wed Feb  2 23:16:58 2011 nBits=207fffff nNonce=00000002 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=6051 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_version(nVersion=70016 nServices=9 nTime=Wed Mar  8 04:33:39 2023 addrTo=CAddress(nServices=1 net=IPv4 addr=0 port=0) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x5D55852BE28ACE43 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_version(nVersion=70016 nServices=1033 nTime=Wed Mar  8 04:34:17 2023 addrTo=CAddress(nServices=0 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xC517320E6DAF59DF strSubVer=/Satoshi:24.99.0(testnode0)/ nStartingHeight=0 relay=1) 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
 node0 2023-03-08T04:34:17.067949Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-08T04:34:17.095135Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 peer=0 
 node0 2023-03-08T04:34:17.314623Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364 (17) peer=0 
 node0 2023-03-08T04:34:17.316018Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-08T04:34:17.317000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364)]) 
 test  2023-03-08T04:34:17.317000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0b71784b174e34d19f54b019952d9437840aa0eb458132ccb8cf288d744bb853 hashMerkleRoot=e38415c928ce45c0ddc5953dae43e2141e829495004310deab10956a3d0b9ca8 nTime=Wed Feb  2 23:16:59 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0111 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-08T04:34:17.318461Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=1 
 node0 2023-03-08T04:34:17.320401Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1 
 test  2023-03-08T04:34:17.321000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
 node0 2023-03-08T04:34:17.321425Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1 
 test  2023-03-08T04:34:17.322000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
 node0 2023-03-08T04:34:17.325952Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=1 
 test  2023-03-08T04:34:17.326000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
 node0 2023-03-08T04:34:17.327751Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=1 
 test  2023-03-08T04:34:17.328000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
 node0 2023-03-08T04:34:17.329015Z [msghand] [net_processing.cpp:3366] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70016, blocks=-1, us=0.0.0.0:0, txrelay=1, peer=1 
 test  2023-03-08T04:34:17.337000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
 node0 2023-03-08T04:34:17.341056Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1 
 node0 2023-03-08T04:34:17.342075Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-08T04:34:17.344183Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e peer=0 
 node0 2023-03-08T04:34:17.501499Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0 (18) peer=0 
 test  2023-03-08T04:34:17.503000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0)]) 
 node0 2023-03-08T04:34:17.503060Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-08T04:34:17.504000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364 hashMerkleRoot=e61b5bdba523759dc7426f53e0b11afc2e2ac3358ab85fd441daee896d98e935 nTime=Wed Feb  2 23:17:00 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0112 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-08T04:34:17.505029Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=1 
 node0 2023-03-08T04:34:17.505860Z [msghand] [net_processing.cpp:3409] [ProcessMessage] New outbound peer connected: version: 70016, blocks=-1, peer=1 (outbound-full-relay) 
 node0 2023-03-08T04:34:17.507897Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1 
 test  2023-03-08T04:34:17.508000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
 node0 2023-03-08T04:34:17.509531Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=1 
 test  2023-03-08T04:34:17.510000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=a55a24eb4e8e7e1a) 
 test  2023-03-08T04:34:17.510000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=a55a24eb4e8e7e1a) 
 node0 2023-03-08T04:34:17.512518Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=1 
 test  2023-03-08T04:34:17.514000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
 node0 2023-03-08T04:34:17.514985Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-08T04:34:17.516419Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 peer=0 
 node0 2023-03-08T04:34:17.672731Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b (19) peer=0 
 node0 2023-03-08T04:34:17.674108Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-08T04:34:17.675000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b)]) 
 test  2023-03-08T04:34:17.675000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0 hashMerkleRoot=5c81c9994bb73d9bc3e1f621f55ea39b0dae38278d0f41144de2b4e12518b82f nTime=Wed Feb  2 23:17:01 2011 nBits=207fffff nNonce=00000001 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0113 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-08T04:34:17.676055Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=1 
 node0 2023-03-08T04:34:17.676743Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=1 
 node0 2023-03-08T04:34:17.678892Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-08T04:34:17.680152Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba peer=0 
 node0 2023-03-08T04:34:17.837257Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566 (20) peer=0 
 node0 2023-03-08T04:34:17.838582Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 test  2023-03-08T04:34:17.839000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566)]) 
 test  2023-03-08T04:34:17.839000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b hashMerkleRoot=70b26d066fed597031248167043f37c1e62220d10f3a48d54545716e9f275f22 nTime=Wed Feb  2 23:17:02 2011 nBits=207fffff nNonce=00000005 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0114 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 node0 2023-03-08T04:34:17.840527Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
 node0 2023-03-08T04:34:17.841295Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=1 
 test  2023-03-08T04:34:17.843000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
 node0 2023-03-08T04:34:17.844040Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-08T04:34:17.845333Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a peer=0 
 test  2023-03-08T04:34:17.897000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_headers(headers=[CBlockHeader(nVersion=4 hashPrevBlock=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 hashMerkleRoot=4a74dde0b97a8704f2aed3db8fcf4f9dc4b52bf99478c2ccd21a6ccc3d8c327f nTime=Wed Feb  2 23:16:43 2011 nBits=207fffff nNonce=00000000), CBlockHeader(nVersion=4 hashPrevBlock=18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Wed Feb  2 23:16:44 2011 nBits=207fffff nNo... (msg truncated) 
 test  2023-03-08T04:34:17.898000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 3 
 test  2023-03-08T04:34:17.898000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12173 should be started 
 test  2023-03-08T04:34:17.898000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
 node0 2023-03-08T04:34:17.989060Z [http] [httpserver.cpp:257] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33714 
 node0 2023-03-08T04:34:18.069483Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
 node0 2023-03-08T04:34:18.070346Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 node0 2023-03-08T04:34:18.073460Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 node0 2023-03-08T04:34:18.075339Z [httpworker.1] [net.cpp:457] [ConnectNode] [net:debug] trying connection 127.0.0.1:12173 lastseen=0.0hrs 
 node0 2023-03-08T04:34:18.076877Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
 node0 2023-03-08T04:34:18.078198Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 peer=0 
 node0 2023-03-08T04:34:18.163118Z [httpworker.1] [net.cpp:2803] [CNode] [net] Added connection peer=2 
 node0 2023-03-08T04:34:18.243066Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695 (22) peer=0 
 node0 2023-03-08T04:34:18.243886Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 node0 2023-03-08T04:34:18.245300Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=1 
 node0 2023-03-08T04:34:18.249221Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
 node0 2023-03-08T04:34:37.325285Z [httpworker.1] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=2 
 test  2023-03-08T04:35:17.908000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           test_function = lambda: self.is_connected
                                   '''
 test  2023-03-08T04:35:17.908000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
                                       self.run_test()
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 77, in run_test
                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 663, in add_outbound_p2p_connection
                                       p2p_conn.wait_for_connect()
                                     File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 467, in wait_for_connect
                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
                                     File "/home/ubuntu/ci_scratch/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 ''''
                                           test_function = lambda: self.is_connected
                                   ''' not true after 60.0 seconds
 test  2023-03-08T04:35:17.909000Z TestFramework (DEBUG): Closing down network thread 
 node0 2023-03-08T04:35:20.557427Z [httpworker.1] [net_processing.cpp:1402] [PushNodeVersion] [net] send version message: version 70016, blocks=0, txrelay=1, peer=2 
 test  2023-03-08T04:35:27.925000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
                                   '''
 test  2023-03-08T04:35:30.950000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606)]) 
 test  2023-03-08T04:35:30.950000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566 hashMerkleRoot=88b88a2c16c9d33a7ae5fa5f728d52ce6d42ccb9733cba3699efc037c227184d nTime=Wed Feb  2 23:17:03 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0115 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
 test  2023-03-08T04:35:30.950000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695)]) 
 test  2023-03-08T04:35:30.950000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_block(block=CBlock(nVersion=4 hashPrevBlock=752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 hashMerkleRoot=4b2d553f063386720c17dc3606b84717f494fb242713d0f59e9b462960924831 nTime=Wed Feb  2 23:17:04 2011 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=0116 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
...
p2p_ibd_stalling.py                                    | ✖ Failed  | 126 s

ALL                                                    | ✖ Failed  | 42880 s (accumulated) 
Runtime: 11402 s
  8. maflcko commented at 8:12 AM on March 8, 2023: member

    Are you running this via the ci system or directly?

  9. maflcko commented at 8:13 AM on March 8, 2023: member

    Ah yes, CI doesn't use --valgrind, so #27221 should make no difference.

  10. maflcko commented at 8:16 AM on March 8, 2023: member

    See:

    So I wonder if the timeout factor of 40 is not applied for some reason. (It will be applied if the test is run by the ci system, but if you run it yourself inside the ci system, it is not applied)

  11. bitcoin deleted a comment on Mar 8, 2023
  12. fanquake commented at 8:40 AM on March 8, 2023: member

    Are you running this via the ci system

    Yea via the CI (native_valgrind.sh). Will look into it.

  13. maflcko commented at 10:33 AM on March 8, 2023: member

    Ok, see https://github.com/bitcoin/bitcoin/pull/27226

  14. fanquake commented at 1:26 PM on March 10, 2023: member

    Fixed by #27226.

  15. fanquake closed this on Mar 10, 2023
  16. bitcoin deleted a comment on Mar 12, 2023
  17. bitcoin locked this on Mar 11, 2024
Contributors
fanquakemaflcko
Labels
BugTests
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: 2026-05-03 15:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me