Issue in `p2p_ibd_stalling.py` under Valgrind #27208

issue fanquake openend this issue on March 6, 2023

fanquake commented at 9:29 am on March 6, 2023: member

At 40c6c85c05812ee8bf824b639307b1ac17a001c4 with the native_valgrind job:

 0 test  2023-03-05T21:26:43.074000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
 1 node0 2023-03-05T21:26:43.265731Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
 2 node0 2023-03-05T21:26:43.267295Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
 3 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 
 4 node0 2023-03-05T21:26:43.271568Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
 5 node0 2023-03-05T21:26:55.588032Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
 6 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 
 7 node0 2023-03-05T21:26:55.731504Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=2 
 8 test  2023-03-05T21:27:43.097000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
 9                                           test_function = lambda: self.is_connected
10                                   '''
11 test  2023-03-05T21:27:43.097000Z TestFramework (ERROR): Assertion failed 
12                                   Traceback (most recent call last):
13                                     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
14                                       self.run_test()
15                                     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
16                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
17                                     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
18                                       p2p_conn.wait_for_connect()
19                                     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
20                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
21                                     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
22                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
23                                   AssertionError: Predicate ''''
24                                           test_function = lambda: self.is_connected
25                                   ''' not true after 60.0 seconds
26 test  2023-03-05T21:27:43.102000Z TestFramework (DEBUG): Closing down network thread 
27 test  2023-03-05T21:27:53.123000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
28                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
29                                   '''
30 node0 2023-03-05T21:28:08.198208Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=1 from eviction 
31 node0 2023-03-05T21:28:08.201820Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=1

fanquake added the label Bug on Mar 6, 2023
fanquake added the label Tests on Mar 6, 2023
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?
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.

fanquake commented at 7:25 pm on March 7, 2023: member

Is there a combined log or similar?

  0............................                                                                                                            170/256 - p2p_ibd_stalling.py failed, Duration: 134 s                     
  1
  2stdout:
  32023-03-07T18:57:54.280000Z TestFramework (INFO): PRNG seed is: 6725125940728086953
  42023-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
  52023-03-07T18:58:07.823000Z TestFramework (INFO): Prepare blocks without sending them to the node
  62023-03-07T18:58:07.897000Z TestFramework (INFO): Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled
  72023-03-07T18:59:48.100000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
  8        test_function = lambda: self.is_connected
  9'''
 102023-03-07T18:59:48.100000Z TestFramework (ERROR): Assertion failed
 11Traceback (most recent call last):
 12  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
 13    self.run_test()
 14  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
 15    peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
 16  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
 17    p2p_conn.wait_for_connect()
 18  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
 19    wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
 20  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
 21    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
 22AssertionError: Predicate ''''
 23        test_function = lambda: self.is_connected
 24''' not true after 60.0 seconds
 252023-03-07T18:59:58.119000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
 26        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
 27'''
 28[node 0] Cleaning up leftover process
 29
 30
 31stderr:
 32Traceback (most recent call last):
 33  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 164, in <module>
 34    P2PIBDStallingTest().main()
 35  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
 36    exit_code = self.shutdown()
 37  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
 38    self.network_thread.close()
 39  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 603, in close
 40    wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
 41  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
 42    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
 43AssertionError: Predicate ''''
 44        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
 45''' not true after 10.0 seconds
 46Task was destroyed but it is pending!
 47task: <Task pending name='Task-9' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/lib/python3.10/asyncio/selector_events.py:193>>
 48/usr/lib/python3.10/asyncio/base_events.py:671: RuntimeWarning: coroutine 'BaseSelectorEventLoop._accept_connection2' was never awaited
 49
 50
 51Combine the logs and print the last 99999999 lines ...
 52
 53============
 54Combined log for /home/ubuntu/ci_scratch/ci/scratch/test_runner//test_runner_₿_🏃_20230307_155148/p2p_ibd_stalling_97:
 55============
 56
 57 test  2023-03-07T18:57:54.280000Z TestFramework (INFO): PRNG seed is: 6725125940728086953 
 58 test  2023-03-07T18:57:54.280000Z TestFramework (DEBUG): Setting up network thread 
 59 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 
 60 test  2023-03-07T18:57:54.282000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 61 node0 2023-03-07T18:57:58.877542Z [init] [init/common.cpp:149] [LogPackageVersion] Bitcoin Core version v24.99.0-86bacd75e76e (release build) 
 62 node0 2023-03-07T18:57:58.919600Z [init] [init.cpp:680] [InitParameterInteraction] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 63 node0 2023-03-07T18:58:00.668764Z [init] [kernel/context.cpp:21] [Context] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 64 node0 2023-03-07T18:58:00.672072Z [init] [random.cpp:99] [ReportHardwareRand] Using RdSeed as an additional entropy source 
 65 node0 2023-03-07T18:58:00.673155Z [init] [random.cpp:102] [ReportHardwareRand] Using RdRand as an additional entropy source 
 66 node0 2023-03-07T18:58:01.412897Z [init] [init/common.cpp:120] [StartLogging] Default data directory /home/nonroot/.bitcoin 
 67 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 
 68 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 
 69 node0 2023-03-07T18:58:01.426618Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: regtest="1" 
 70 node0 2023-03-07T18:58:01.429110Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 71 node0 2023-03-07T18:58:01.429590Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 72 node0 2023-03-07T18:58:01.430056Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 73 node0 2023-03-07T18:58:01.430532Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 74 node0 2023-03-07T18:58:01.431006Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 75 node0 2023-03-07T18:58:01.431457Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 76 node0 2023-03-07T18:58:01.431933Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 77 node0 2023-03-07T18:58:01.432386Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 78 node0 2023-03-07T18:58:01.432837Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 79 node0 2023-03-07T18:58:01.433304Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999" 
 80 node0 2023-03-07T18:58:01.433795Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] port="12164" 
 81 node0 2023-03-07T18:58:01.434310Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 82 node0 2023-03-07T18:58:01.434842Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1" 
 83 node0 2023-03-07T18:58:01.435364Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcport="17164" 
 84 node0 2023-03-07T18:58:01.435879Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] server="1" 
 85 node0 2023-03-07T18:58:01.436374Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 86 node0 2023-03-07T18:58:01.436854Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 87 node0 2023-03-07T18:58:01.437302Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] upnp="0" 
 88 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" 
 89 node0 2023-03-07T18:58:01.439366Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debug="" 
 90 node0 2023-03-07T18:58:01.439860Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 91 node0 2023-03-07T18:58:01.440342Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 92 node0 2023-03-07T18:58:01.440820Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="rand" 
 93 node0 2023-03-07T18:58:01.441272Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: disablewallet="" 
 94 node0 2023-03-07T18:58:01.441774Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: loglevel="trace" 
 95 node0 2023-03-07T18:58:01.442265Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 96 node0 2023-03-07T18:58:01.442769Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logthreadnames="" 
 97 node0 2023-03-07T18:58:01.443248Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logtimemicros="" 
 98 node0 2023-03-07T18:58:01.443766Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 99 node0 2023-03-07T18:58:01.447151Z [init] [init.cpp:1124] [AppInitMain] Using at most 125 automatic connections (1048564 file descriptors available) 
100 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 
101 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 
102 node0 2023-03-07T18:58:01.958846Z [init] [init.cpp:1156] [AppInitMain] Script verification uses 15 additional threads 
103 node0 2023-03-07T18:58:02.389437Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start 
104 node0 2023-03-07T18:58:02.437801Z [init] [wallet/init.cpp:132] [Construct] Wallet disabled! 
105 node0 2023-03-07T18:58:04.348117Z [init] [httpserver.cpp:192] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
106 node0 2023-03-07T18:58:04.397260Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 
107 node0 2023-03-07T18:58:04.413197Z [init] [httpserver.cpp:378] [libevent_log_cb] [libevent:warning] getaddrinfo: address family for nodename not supported 
108 node0 2023-03-07T18:58:04.415194Z [init] [httpserver.cpp:346] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 failed. 
109 node0 2023-03-07T18:58:04.416023Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 17164 
110 node0 2023-03-07T18:58:04.440550Z [init] [httpserver.cpp:417] [InitHTTPServer] [http] Initialized HTTP server 
111 node0 2023-03-07T18:58:04.443111Z [init] [httpserver.cpp:419] [InitHTTPServer] [http] creating work queue of depth 16 
112 node0 2023-03-07T18:58:04.459267Z [init] [rpc/server.cpp:289] [StartRPC] [rpc] Starting RPC 
113 node0 2023-03-07T18:58:04.534013Z [init] [httprpc.cpp:296] [StartHTTPRPC] [rpc] Starting HTTP RPC server 
114 node0 2023-03-07T18:58:04.536091Z [init] [httprpc.cpp:245] [InitRPCAuthentication] Using random cookie authentication. 
115 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 
116 node0 2023-03-07T18:58:04.554112Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1) 
117 node0 2023-03-07T18:58:04.571066Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0) 
118 node0 2023-03-07T18:58:04.582184Z [init] [httpserver.cpp:441] [StartHTTPServer] [http] Starting HTTP server 
119 node0 2023-03-07T18:58:04.583679Z [init] [httpserver.cpp:443] [StartHTTPServer] [http] starting 4 worker threads 
120 node0 2023-03-07T18:58:04.722619Z [init] [init.cpp:1241] [AppInitMain] Using /16 prefix for IP bucketing 
121 node0 2023-03-07T18:58:04.755641Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading P2P addresses… 
122 node0 2023-03-07T18:58:04.793085Z [http] [httpserver.cpp:304] [ThreadHTTP] [http] Entering http event loop 
123 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") 
124 node0 2023-03-07T18:58:04.948138Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading banlist… 
125 node0 2023-03-07T18:58:05.018579Z [init] [banman.cpp:41] [LoadBanlist] Recreating the banlist database 
126 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 
127 node0 2023-03-07T18:58:05.082656Z [init] [banman.cpp:67] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  50ms 
128 node0 2023-03-07T18:58:05.117763Z [init] [net.cpp:1561] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false 
129 node0 2023-03-07T18:58:05.206330Z [init] [net.cpp:2236] [SetNetworkActive] SetNetworkActive: true 
130 node0 2023-03-07T18:58:05.319634Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
131 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. 
132 node0 2023-03-07T18:58:05.435100Z [init] [init.cpp:1456] [AppInitMain] Cache configuration: 
133 node0 2023-03-07T18:58:05.443491Z [init] [init.cpp:1457] [AppInitMain] * Using 2.0 MiB for block index database 
134 node0 2023-03-07T18:58:05.459910Z [init] [init.cpp:1465] [AppInitMain] * Using 8.0 MiB for chain state database 
135 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) 
136 node0 2023-03-07T18:58:05.568239Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading block index… 
137 node0 2023-03-07T18:58:05.575716Z [init] [node/chainstate.cpp:41] [LoadChainstate] Validating signatures for all blocks. 
138 node0 2023-03-07T18:58:05.580071Z [init] [node/chainstate.cpp:43] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
139 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 
140 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 
141 node0 2023-03-07T18:58:05.756214Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
142 node0 2023-03-07T18:58:05.819815Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
143 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 
144 node0 2023-03-07T18:58:05.929484Z [init] [node/blockstorage.cpp:331] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
145 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) 
146 node0 2023-03-07T18:58:05.943096Z [init] [node/blockstorage.cpp:346] [LoadBlockIndexDB] Checking all blk files are present... 
147 node0 2023-03-07T18:58:05.955227Z [init] [validation.cpp:4432] [LoadBlockIndex] Initializing databases... 
148 node0 2023-03-07T18:58:05.997829Z [init] [flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x1000000 in blk00000.dat 
149 node0 2023-03-07T18:58:06.116950Z [init] [node/chainstate.cpp:124] [LoadChainstate] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
150 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 
151 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 
152 node0 2023-03-07T18:58:06.127331Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
153 node0 2023-03-07T18:58:06.136827Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
154 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 
155 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 
156 node0 2023-03-07T18:58:06.243967Z [init] [validation.cpp:5316] [MaybeRebalanceCaches] [snapshot] allocating all cache to the IBD chainstate 
157 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 
158 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 
159 node0 2023-03-07T18:58:06.457951Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
160 node0 2023-03-07T18:58:06.471165Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
161 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 
162 node0 2023-03-07T18:58:06.529230Z [init] [validation.cpp:4859] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinsdb cache to 8.0 MiB 
163 node0 2023-03-07T18:58:06.530749Z [init] [validation.cpp:4861] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinstip cache to 440.0 MiB 
164 node0 2023-03-07T18:58:06.547340Z [init] [noui.cpp:56] [noui_InitMessage] init message: Verifying blocks… 
165 node0 2023-03-07T18:58:06.556832Z [init] [init.cpp:1526] [AppInitMain]  block index             986ms 
166 node0 2023-03-07T18:58:06.672492Z [init] [init.cpp:1615] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
167 node0 2023-03-07T18:58:06.728696Z [loadblk] [util/thread.cpp:20] [TraceThread] loadblk thread start 
168 node0 2023-03-07T18:58:06.856607Z [loadblk] [validation.cpp:2821] [ConnectTip] [bench]   - Load block from disk: 68.33ms [0.07s (infms/blk)] 
169 node0 2023-03-07T18:58:06.898101Z [loadblk] [validationinterface.cpp:255] [BlockChecked] [validation] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
170 node0 2023-03-07T18:58:06.914070Z [loadblk] [validation.cpp:2837] [ConnectTip] [bench]   - Connect total: 65.43ms [0.07s (65.43ms/blk)] 
171 node0 2023-03-07T18:58:06.919434Z [loadblk] [validation.cpp:2846] [ConnectTip] [bench]   - Flush: 5.47ms [0.01s (5.47ms/blk)] 
172 node0 2023-03-07T18:58:06.921838Z [loadblk] [validation.cpp:2856] [ConnectTip] [bench]   - Writing chainstate: 2.43ms [0.00s (2.43ms/blk)] 
173 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) 
174 node0 2023-03-07T18:58:06.970412Z [loadblk] [validation.cpp:2872] [ConnectTip] [bench]   - Connect postprocess: 48.43ms [0.05s (48.43ms/blk)] 
175 node0 2023-03-07T18:58:06.971974Z [loadblk] [validation.cpp:2876] [ConnectTip] [bench] - Connect block: 190.09ms [0.19s (190.09ms/blk)] 
176 node0 2023-03-07T18:58:06.995432Z [loadblk] [txmempool.cpp:644] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
177 node0 2023-03-07T18:58:07.018881Z [loadblk] [validationinterface.cpp:232] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
178 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 
179 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) 
180 node0 2023-03-07T18:58:07.058721Z [scheduler] [validationinterface.cpp:232] [operator()] [validation] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
181 node0 2023-03-07T18:58:07.108662Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
182 node0 2023-03-07T18:58:07.185730Z [loadblk] [kernel/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file from disk. Continuing anyway. 
183 node0 2023-03-07T18:58:07.192367Z [loadblk] [util/thread.cpp:22] [TraceThread] loadblk thread exit 
184 node0 2023-03-07T18:58:07.199416Z [init] [init.cpp:1702] [AppInitMain] block tree size = 1 
185 node0 2023-03-07T18:58:07.201669Z [init] [init.cpp:1714] [AppInitMain] nBestHeight = 0 
186 node0 2023-03-07T18:58:07.265546Z [init] [net.cpp:2169] [BindListenPort] Bound to 127.0.0.1:12164 
187 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. 
188 node0 2023-03-07T18:58:07.305861Z [init] [noui.cpp:56] [noui_InitMessage] init message: Starting network threads… 
189 node0 2023-03-07T18:58:07.343357Z [init] [net.cpp:2375] [Start] DNS seeding disabled 
190 node0 2023-03-07T18:58:07.407367Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
191 node0 2023-03-07T18:58:07.436083Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
192 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) 
193 node0 2023-03-07T18:58:07.497174Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
194 node0 2023-03-07T18:58:07.497699Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
195 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 
196 node0 2023-03-07T18:58:07.560667Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
197 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 
198 node0 2023-03-07T18:58:07.613064Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
199 test  2023-03-07T18:58:07.663000Z TestFramework.node0 (DEBUG): RPC successfully started 
200 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 
201 node0 2023-03-07T18:58:07.667926Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
202 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 
203 node0 2023-03-07T18:58:07.677699Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
204 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 
205 node0 2023-03-07T18:58:07.703867Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
206 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 
207 node0 2023-03-07T18:58:07.762318Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
208 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 
209 node0 2023-03-07T18:58:07.767559Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
210 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 
211 node0 2023-03-07T18:58:07.773406Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
212 test  2023-03-07T18:58:07.823000Z TestFramework (INFO): Prepare blocks without sending them to the node 
213 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 
214 test  2023-03-07T18:58:07.897000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 1 
215 test  2023-03-07T18:58:07.897000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12175 should be started 
216 test  2023-03-07T18:58:07.897000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12175 outbound-full-relay 
217 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 
218 node0 2023-03-07T18:58:07.901557Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
219 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 
220 node0 2023-03-07T18:58:08.046809Z [httpworker.2] [net.cpp:2803] [CNode] [net] Added connection peer=0 
221 node0 2023-03-07T18:58:08.144873Z [httpworker.2] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=0 
222 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 
223 test  2023-03-07T18:58:08.191000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
224 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) 
225 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) 
226 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
227 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
228 test  2023-03-07T18:58:08.192000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
229 node0 2023-03-07T18:58:08.284544Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=0 
230 node0 2023-03-07T18:58:08.307101Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=0 
231 test  2023-03-07T18:58:08.308000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
232 node0 2023-03-07T18:58:08.308796Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=0 
233 test  2023-03-07T18:58:08.309000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
234 node0 2023-03-07T18:58:08.328742Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=0 
235 test  2023-03-07T18:58:08.330000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
236 node0 2023-03-07T18:58:08.344965Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=0 
237 test  2023-03-07T18:58:08.345000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
238 test  2023-03-07T18:58:08.348000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
239 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 
240 node0 2023-03-07T18:58:08.385242Z [msghand] [timedata.cpp:57] [AddTimeData] [net] added time data, samples 2, offset -1 (+0 minutes) 
241 node0 2023-03-07T18:58:08.395502Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=0 
242 node0 2023-03-07T18:58:08.398039Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=0 
243 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) 
244 node0 2023-03-07T18:58:08.407199Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=0 
245 test  2023-03-07T18:58:08.408000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
246 test  2023-03-07T18:58:08.422000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=29efaad9ba235612) 
247 node0 2023-03-07T18:58:08.422053Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=0 
248 test  2023-03-07T18:58:08.423000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=29efaad9ba235612) 
249 node0 2023-03-07T18:58:08.463141Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getheaders (69 bytes) peer=0 
250 test  2023-03-07T18:58:08.464000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getheaders(locator=CBlockLocator(vHave=[7041830694386478471858881810674310864173988660927928131397671070347943617030]), stop=0000000000000000000000000000000000000000000000000000000000000000) 
251 node0 2023-03-07T18:58:08.468601Z [msghand] [net_processing.cpp:5428] [SendMessages] [net] initial getheaders (0) to peer=0 (startheight:-1) 
252 node0 2023-03-07T18:58:08.578692Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=0 
253 test  2023-03-07T18:58:08.580000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
254 node0 2023-03-07T18:58:08.582867Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=0 
255 node0 2023-03-07T18:58:08.587656Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=0 
256 node0 2023-03-07T18:58:08.592392Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=0 
257 node0 2023-03-07T18:58:08.593933Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=0 
258 test  2023-03-07T18:58:08.594000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
259 node0 2023-03-07T18:58:08.596070Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=0 
260 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) 
261 test  2023-03-07T18:58:08.615000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 2 
262 test  2023-03-07T18:58:08.615000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12174 should be started 
263 test  2023-03-07T18:58:08.615000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12174 outbound-full-relay 
264 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 
265 node0 2023-03-07T18:58:08.684640Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=0 
266 node0 2023-03-07T18:58:33.760456Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
267 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 
268 node0 2023-03-07T18:58:46.835711Z [msghand] [validation.cpp:3832] [ProcessNewBlockHeaders] Synchronizing blockheaders, height: 1024 (~0.16%) 
269 node0 2023-03-07T18:58:46.841966Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=0 from eviction 
270 node0 2023-03-07T18:58:46.854538Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=0 
271 node0 2023-03-07T18:58:46.857799Z [httpworker.1] [net.cpp:2803] [CNode] [net] Added connection peer=1 
272 node0 2023-03-07T18:58:46.908586Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 (1) peer=0 
273 node0 2023-03-07T18:58:46.913399Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 (2) peer=0 
274 node0 2023-03-07T18:58:46.915028Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e (3) peer=0 
275 node0 2023-03-07T18:58:46.916177Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 (4) peer=0 
276 node0 2023-03-07T18:58:46.916813Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba (5) peer=0 
277 node0 2023-03-07T18:58:46.917881Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a (6) peer=0 
278 node0 2023-03-07T18:58:46.918506Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 (7) peer=0 
279 node0 2023-03-07T18:58:46.919101Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 (8) peer=0 
280 node0 2023-03-07T18:58:46.919726Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b (9) peer=0 
281 node0 2023-03-07T18:58:46.920318Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 (10) peer=0 
282 node0 2023-03-07T18:58:46.920922Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 (11) peer=0 
283 node0 2023-03-07T18:58:46.921525Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 5085f9b6a36365c466b6d84c96e74d7e135b245909bf37d2dc3169ae3fd8a358 (12) peer=0 
284 node0 2023-03-07T18:58:46.922130Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 7c7867082cd45356564ebb64ba8004c756d694015b9f13ecd2e4161f2083e041 (13) peer=0 
285 node0 2023-03-07T18:58:46.922749Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0db9883db92373bdb4c76b364dd8f884cef440ce7a199671e9d8772e4f51ec9e (14) peer=0 
286 node0 2023-03-07T18:58:46.923344Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3efdfa1d6b4515648862589e3887ee60471334ce1b816af8ab4ef7319742d81e (15) peer=0 
287 node0 2023-03-07T18:58:46.923940Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0b71784b174e34d19f54b019952d9437840aa0eb458132ccb8cf288d744bb853 (16) peer=0 
288 node0 2023-03-07T18:58:46.932237Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (577 bytes) peer=0 
289 node0 2023-03-07T18:58:46.938497Z [httpworker.1] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=1 
290 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 
291 test  2023-03-07T18:58:46.943000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendheaders() 
292 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) 
293 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) 
294 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) 
295 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) 
296 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) 
297 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) 
298 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) 
299 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) 
300 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) 
301 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) 
302 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) 
303 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) 
304 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) 
305 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) 
306 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) 
307 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) 
308 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
309 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) 
310 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) 
311 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
312 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
313 test  2023-03-07T18:58:46.945000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
314 node0 2023-03-07T18:58:46.955692Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
315 node0 2023-03-07T18:58:46.983249Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 peer=0 
316 node0 2023-03-07T18:58:47.206395Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364 (17) peer=0 
317 node0 2023-03-07T18:58:47.208013Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
318 test  2023-03-07T18:58:47.209000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364)]) 
319 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) 
320 node0 2023-03-07T18:58:47.210079Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=1 
321 node0 2023-03-07T18:58:47.211209Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1 
322 test  2023-03-07T18:58:47.213000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
323 node0 2023-03-07T18:58:47.213557Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1 
324 test  2023-03-07T18:58:47.214000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
325 node0 2023-03-07T18:58:47.217932Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=1 
326 test  2023-03-07T18:58:47.218000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
327 node0 2023-03-07T18:58:47.219676Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=1 
328 test  2023-03-07T18:58:47.220000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
329 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 
330 node0 2023-03-07T18:58:47.231454Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
331 test  2023-03-07T18:58:47.232000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
332 node0 2023-03-07T18:58:47.232798Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e peer=0 
333 node0 2023-03-07T18:58:47.392314Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0 (18) peer=0 
334 node0 2023-03-07T18:58:47.393081Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
335 test  2023-03-07T18:58:47.394000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0)]) 
336 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) 
337 node0 2023-03-07T18:58:47.395036Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
338 node0 2023-03-07T18:58:47.396325Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 peer=0 
339 node0 2023-03-07T18:58:47.556421Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b (19) peer=0 
340 node0 2023-03-07T18:58:47.557962Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
341 test  2023-03-07T18:58:47.558000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b)]) 
342 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) 
343 node0 2023-03-07T18:58:47.559328Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1 
344 node0 2023-03-07T18:58:47.560703Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=1 
345 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) 
346 node0 2023-03-07T18:58:47.562801Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1 
347 test  2023-03-07T18:58:47.563000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
348 test  2023-03-07T18:58:47.564000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=cc5de4d1af85f04c) 
349 test  2023-03-07T18:58:47.564000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=cc5de4d1af85f04c) 
350 node0 2023-03-07T18:58:47.564254Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=1 
351 node0 2023-03-07T18:58:47.567248Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=1 
352 test  2023-03-07T18:58:47.569000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
353 node0 2023-03-07T18:58:47.569917Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
354 node0 2023-03-07T18:58:47.571210Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba peer=0 
355 node0 2023-03-07T18:58:47.730576Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566 (20) peer=0 
356 node0 2023-03-07T18:58:47.731335Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
357 test  2023-03-07T18:58:47.732000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566)]) 
358 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) 
359 node0 2023-03-07T18:58:47.733223Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
360 node0 2023-03-07T18:58:47.734613Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a peer=0 
361 node0 2023-03-07T18:58:47.894775Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
362 node0 2023-03-07T18:58:47.895530Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
363 test  2023-03-07T18:58:47.897000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606)]) 
364 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) 
365 node0 2023-03-07T18:58:47.897709Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=1 
366 node0 2023-03-07T18:58:47.898495Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=1 
367 node0 2023-03-07T18:58:47.902386Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
368 node0 2023-03-07T18:58:47.903681Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 peer=0 
369 node0 2023-03-07T18:58:48.062975Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695 (22) peer=0 
370 node0 2023-03-07T18:58:48.063734Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
371 test  2023-03-07T18:58:48.065000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695)]) 
372 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) 
373 node0 2023-03-07T18:58:48.065945Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
374 node0 2023-03-07T18:58:48.066734Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=1 
375 test  2023-03-07T18:58:48.067000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
376 node0 2023-03-07T18:58:48.070071Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
377 node0 2023-03-07T18:58:48.071994Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 peer=0 
378 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) 
379 test  2023-03-07T18:58:48.093000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 3 
380 test  2023-03-07T18:58:48.094000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12173 should be started 
381 test  2023-03-07T18:58:48.094000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
382 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 
383 node0 2023-03-07T18:58:48.322924Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 08aa76b207041d4ca67a570c816e7f577456fcdb435f8116cd929310a8be036b (23) peer=0 
384 node0 2023-03-07T18:58:48.323684Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
385 node0 2023-03-07T18:58:48.326238Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
386 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 
387 node0 2023-03-07T18:58:48.329268Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=1 
388 node0 2023-03-07T18:58:48.331071Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
389 node0 2023-03-07T18:59:36.109346Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=2 
390 test  2023-03-07T18:59:48.100000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
391                                           test_function = lambda: self.is_connected
392                                   '''
393 test  2023-03-07T18:59:48.100000Z TestFramework (ERROR): Assertion failed 
394                                   Traceback (most recent call last):
395                                     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
396                                       self.run_test()
397                                     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
398                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
399                                     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
400                                       p2p_conn.wait_for_connect()
401                                     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
402                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
403                                     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
404                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
405                                   AssertionError: Predicate ''''
406                                           test_function = lambda: self.is_connected
407                                   ''' not true after 60.0 seconds
408 test  2023-03-07T18:59:48.103000Z TestFramework (DEBUG): Closing down network thread 
409 test  2023-03-07T18:59:58.119000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
410                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
411                                   '''
412 node0 2023-03-07T19:00:07.633394Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=1 from eviction 
413 node0 2023-03-07T19:00:07.635479Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=1 
414 node0 2023-03-07T19:00:07.638418Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 32d0a4daa0df30241959a213af52f872502e73b095ddbe5323a208b904a73cb1 (24) peer=1 
415 node0 2023-03-07T19:00:07.639121Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 09f3aa3df2944b2ceeba47e792c6d96b41d724b390a052d320ca22d9e2de9012 (25) peer=1 
416 node0 2023-03-07T19:00:07.639828Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3b754dfb708ce6b74d4955c29408e42bcf3a0e4ad466324ba8f14956f407ffea (26) peer=1 
417 node0 2023-03-07T19:00:07.640492Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 75046beae1a2feaf24485e346fb1d33cbabf26f206e471ef37e3e7fdfefefed6 (27) peer=1 
418 node0 2023-03-07T19:00:07.641143Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 164122b380be7b31386bba20ce51464289202b918cdff4714cc8cb582246322f (28) peer=1 
419 node0 2023-03-07T19:00:07.641771Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 102cfea750c1bb27441ab8d9b2abceafc668adc73fac1daf9ca81f4cb0197100 (29) peer=1 
420 node0 2023-03-07T19:00:07.642402Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 012e6ae5ac239038986efefbfbacabfe7e35f41f63ebac5ebab8125672e374bb (30) peer=1 
421 node0 2023-03-07T19:00:07.643026Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 5e5053b392b2df297fcd3f6017c349fa1ca96ad55b455011ac799b103be031e6 (31) peer=1 
422 node0 2023-03-07T19:00:07.643676Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 28ed8e55724939c57a82bd0dbc913d2341d116e59ca8252c4d6d9cbf02090296 (32) peer=1 
423 node0 2023-03-07T19:00:07.644301Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 7e1208f27dec5a96694ee5ca803b723dfdc09cc9a19ea94131539f14c098ecd2 (33) peer=1 
424 node0 2023-03-07T19:00:07.644915Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2041edbf200026cb6acc76934baad2fdb5d66b0bb039ee3492f6cf440c003c69 (34) peer=1 
425 node0 2023-03-07T19:00:07.645529Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 721e244470287bf477524deb06cbc5a177ad514494584dfcc3a56ef289cf3804 (35) peer=1 
426 node0 2023-03-07T19:00:07.646150Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0c73b90ebf04b40e3df140fcea633d2df7f0a6b42c9a3a79c372672a518e8d4f (36) peer=1 
427 node0 2023-03-07T19:00:07.646803Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 76194c04ce42a14619061cd661823b0e278a05e3c1328248faf4875aa7ecc2bc (37) peer=1 
428 node0 2023-03-07T19:00:07.647418Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 776f4c9d49066296f07e33989dc8b009ae039a98f531af0456973e963f78271d (38) peer=1 
429 node0 2023-03-07T19:00:07.648038Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 4bb31266b2154fe7a748d067bb4105834dbbc300c7ba0caa408d080288b1f9e2 (39) peer=1 
430 node0 2023-03-07T19:00:07.649667Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (577 bytes) peer=1 
431 node0 2023-03-07T19:00:07.651723Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
432 node0 2023-03-07T19:00:07.653059Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b peer=0 
433 node0 2023-03-07T19:00:07.814636Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6551539089fe92307bce623870921c1ff450de87039bd618d28d8aeb17ca677f (40) peer=0 
434 node0 2023-03-07T19:00:07.816036Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
435 node0 2023-03-07T19:00:07.819371Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
436 node0 2023-03-07T19:00:07.829629Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 peer=0 
437 node0 2023-03-07T19:00:07.923337Z [httpworker.0] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=2 
438 node0 2023-03-07T19:00:08.011615Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 4e4ec0e940718b46978e8b83fa465ed9ea8db3dd1c45981f81e3b3f800e852a3 (41) peer=0 
439 node0 2023-03-07T19:00:08.013471Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
440 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 
441 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=08aa76b207041d4ca67a570c816e7f577456fcdb435f8116cd929310a8be036b)]) 
442 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) 
443 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=6551539089fe92307bce623870921c1ff450de87039bd618d28d8aeb17ca677f)]) 
444 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) 
445 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=4e4ec0e940718b46978e8b83fa465ed9ea8db3dd1c45981f81e3b3f800e852a3)]) 
446 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) 
447 test  2023-03-07T19:00:08.031000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendheaders() 
448 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) 
449 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) 
450 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) 
451 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) 
452 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) 
453 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) 
454 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) 
455 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) 
456 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) 
457 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) 
458 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) 
459 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) 
460 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) 
461 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) 
462 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) 
463 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) 
464 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) 
465 node0 2023-03-07T19:00:08.032744Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
466 node0 2023-03-07T19:00:08.036905Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 peer=0 
467 node0 2023-03-07T19:00:08.152474Z [net] [net.cpp:1349] [SocketHandlerConnected] [net] socket closed for peer=0 
468 node0 2023-03-07T19:00:08.155131Z [net] [net.cpp:589] [CloseSocketDisconnect] [net] disconnecting peer=0 
469 node0 2023-03-07T19:00:08.328634Z [net] [net_processing.cpp:1538] [FinalizeNode] [net] Cleared nodestate for peer=0

fanquake commented at 7:53 am on March 8, 2023: member

Log after running with #27221:

  0...............................................................................................                                                                                                           162/256 - p2p_ibd_stalling.py failed, Duration: 126 s
  1
  2stdout:
  32023-03-08T04:33:24.745000Z TestFramework (INFO): PRNG seed is: 3703385557670057473
  42023-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
  52023-03-08T04:33:38.260000Z TestFramework (INFO): Prepare blocks without sending them to the node
  62023-03-08T04:33:38.356000Z TestFramework (INFO): Check that a staller does not get disconnected if the 1024 block lookahead buffer is filled
  72023-03-08T04:35:17.908000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
  8        test_function = lambda: self.is_connected
  9'''
 102023-03-08T04:35:17.908000Z TestFramework (ERROR): Assertion failed
 11Traceback (most recent call last):
 12  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
 13    self.run_test()
 14  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
 15    peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
 16  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
 17    p2p_conn.wait_for_connect()
 18  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
 19    wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
 20  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
 21    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
 22AssertionError: Predicate ''''
 23        test_function = lambda: self.is_connected
 24''' not true after 60.0 seconds
 252023-03-08T04:35:27.925000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
 26        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
 27'''
 28[node 0] Cleaning up leftover process
 29
 30
 31stderr:
 32Traceback (most recent call last):
 33  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_ibd_stalling.py", line 164, in <module>
 34    P2PIBDStallingTest().main()
 35  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
 36    exit_code = self.shutdown()
 37  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
 38    self.network_thread.close()
 39  File "/home/ubuntu/ci_scratch/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/p2p.py", line 603, in close
 40    wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
 41  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
 42    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
 43AssertionError: Predicate ''''
 44        wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
 45''' not true after 10.0 seconds
 46Task was destroyed but it is pending!
 47task: <Task pending name='Task-9' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/lib/python3.10/asyncio/selector_events.py:193>>
 48/usr/lib/python3.10/asyncio/base_events.py:671: RuntimeWarning: coroutine 'BaseSelectorEventLoop._accept_connection2' was never awaited
 49
 50
 51Combine the logs and print the last 99999999 lines ...
 52
 53============
 54Combined log for /home/ubuntu/ci_scratch/ci/scratch/test_runner//test_runner_₿_🏃_20230308_012459/p2p_ibd_stalling_97:
 55============
 56
 57 test  2023-03-08T04:33:24.745000Z TestFramework (INFO): PRNG seed is: 3703385557670057473 
 58 test  2023-03-08T04:33:24.745000Z TestFramework (DEBUG): Setting up network thread 
 59 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 
 60 test  2023-03-08T04:33:24.746000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 61 node0 2023-03-08T04:33:29.336044Z [init] [init/common.cpp:149] [LogPackageVersion] Bitcoin Core version v24.99.0-fa27cf4cc7c2 (release build) 
 62 node0 2023-03-08T04:33:29.378276Z [init] [init.cpp:680] [InitParameterInteraction] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 63 node0 2023-03-08T04:33:31.125717Z [init] [kernel/context.cpp:21] [Context] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 64 node0 2023-03-08T04:33:31.129019Z [init] [random.cpp:99] [ReportHardwareRand] Using RdSeed as an additional entropy source 
 65 node0 2023-03-08T04:33:31.130115Z [init] [random.cpp:102] [ReportHardwareRand] Using RdRand as an additional entropy source 
 66 node0 2023-03-08T04:33:31.874529Z [init] [init/common.cpp:120] [StartLogging] Default data directory /home/nonroot/.bitcoin 
 67 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 
 68 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 
 69 node0 2023-03-08T04:33:31.888176Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: regtest="1" 
 70 node0 2023-03-08T04:33:31.890686Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 71 node0 2023-03-08T04:33:31.891164Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 72 node0 2023-03-08T04:33:31.891638Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 73 node0 2023-03-08T04:33:31.892096Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 74 node0 2023-03-08T04:33:31.892570Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 75 node0 2023-03-08T04:33:31.893051Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 76 node0 2023-03-08T04:33:31.893525Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 77 node0 2023-03-08T04:33:31.893981Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 78 node0 2023-03-08T04:33:31.894434Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 79 node0 2023-03-08T04:33:31.894902Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999" 
 80 node0 2023-03-08T04:33:31.895388Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] port="12164" 
 81 node0 2023-03-08T04:33:31.895898Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 82 node0 2023-03-08T04:33:31.896426Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1" 
 83 node0 2023-03-08T04:33:31.896967Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] rpcport="17164" 
 84 node0 2023-03-08T04:33:31.897491Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] server="1" 
 85 node0 2023-03-08T04:33:31.897990Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 86 node0 2023-03-08T04:33:31.898474Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 87 node0 2023-03-08T04:33:31.898928Z [init] [util/system.cpp:1139] [logArgsPrefix] Config file arg: [regtest] upnp="0" 
 88 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" 
 89 node0 2023-03-08T04:33:31.901007Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debug="" 
 90 node0 2023-03-08T04:33:31.901512Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 91 node0 2023-03-08T04:33:31.902005Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 92 node0 2023-03-08T04:33:31.902489Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: debugexclude="rand" 
 93 node0 2023-03-08T04:33:31.902944Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: disablewallet="" 
 94 node0 2023-03-08T04:33:31.903443Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: loglevel="trace" 
 95 node0 2023-03-08T04:33:31.903945Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 96 node0 2023-03-08T04:33:31.904429Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logthreadnames="" 
 97 node0 2023-03-08T04:33:31.904911Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: logtimemicros="" 
 98 node0 2023-03-08T04:33:31.905450Z [init] [util/system.cpp:1139] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 99 node0 2023-03-08T04:33:31.908828Z [init] [init.cpp:1124] [AppInitMain] Using at most 125 automatic connections (1048564 file descriptors available) 
100 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 
101 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 
102 node0 2023-03-08T04:33:32.417869Z [init] [init.cpp:1156] [AppInitMain] Script verification uses 15 additional threads 
103 node0 2023-03-08T04:33:32.847727Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start 
104 node0 2023-03-08T04:33:32.891199Z [init] [wallet/init.cpp:132] [Construct] Wallet disabled! 
105 node0 2023-03-08T04:33:34.823369Z [init] [httpserver.cpp:192] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
106 node0 2023-03-08T04:33:34.872094Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 
107 node0 2023-03-08T04:33:34.887951Z [init] [httpserver.cpp:378] [libevent_log_cb] [libevent:warning] getaddrinfo: address family for nodename not supported 
108 node0 2023-03-08T04:33:34.889937Z [init] [httpserver.cpp:346] [HTTPBindAddresses] Binding RPC on address ::1 port 17164 failed. 
109 node0 2023-03-08T04:33:34.890775Z [init] [httpserver.cpp:337] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 17164 
110 node0 2023-03-08T04:33:34.915227Z [init] [httpserver.cpp:417] [InitHTTPServer] [http] Initialized HTTP server 
111 node0 2023-03-08T04:33:34.917758Z [init] [httpserver.cpp:419] [InitHTTPServer] [http] creating work queue of depth 16 
112 node0 2023-03-08T04:33:34.933872Z [init] [rpc/server.cpp:289] [StartRPC] [rpc] Starting RPC 
113 node0 2023-03-08T04:33:35.008280Z [init] [httprpc.cpp:296] [StartHTTPRPC] [rpc] Starting HTTP RPC server 
114 node0 2023-03-08T04:33:35.010321Z [init] [httprpc.cpp:245] [InitRPCAuthentication] Using random cookie authentication. 
115 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 
116 node0 2023-03-08T04:33:35.028162Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1) 
117 node0 2023-03-08T04:33:35.045126Z [init] [httpserver.cpp:699] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0) 
118 node0 2023-03-08T04:33:35.056233Z [init] [httpserver.cpp:441] [StartHTTPServer] [http] Starting HTTP server 
119 node0 2023-03-08T04:33:35.057719Z [init] [httpserver.cpp:443] [StartHTTPServer] [http] starting 4 worker threads 
120 node0 2023-03-08T04:33:35.171915Z [http] [httpserver.cpp:304] [ThreadHTTP] [http] Entering http event loop 
121 node0 2023-03-08T04:33:35.202696Z [init] [init.cpp:1241] [AppInitMain] Using /16 prefix for IP bucketing 
122 node0 2023-03-08T04:33:35.235458Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading P2P addresses… 
123 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") 
124 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 
125 node0 2023-03-08T04:33:35.511589Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading banlist… 
126 node0 2023-03-08T04:33:35.580972Z [init] [banman.cpp:41] [LoadBanlist] Recreating the banlist database 
127 node0 2023-03-08T04:33:35.607460Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
128 node0 2023-03-08T04:33:35.640888Z [init] [banman.cpp:67] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  46ms 
129 node0 2023-03-08T04:33:35.696638Z [init] [net.cpp:1561] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false 
130 node0 2023-03-08T04:33:35.720311Z [init] [net.cpp:2236] [SetNetworkActive] SetNetworkActive: true 
131 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. 
132 node0 2023-03-08T04:33:35.910427Z [init] [init.cpp:1456] [AppInitMain] Cache configuration: 
133 node0 2023-03-08T04:33:35.916431Z [init] [init.cpp:1457] [AppInitMain] * Using 2.0 MiB for block index database 
134 node0 2023-03-08T04:33:35.920865Z [init] [init.cpp:1465] [AppInitMain] * Using 8.0 MiB for chain state database 
135 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) 
136 node0 2023-03-08T04:33:36.028711Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading block index… 
137 node0 2023-03-08T04:33:36.036226Z [init] [node/chainstate.cpp:41] [LoadChainstate] Validating signatures for all blocks. 
138 node0 2023-03-08T04:33:36.040953Z [init] [node/chainstate.cpp:43] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
139 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 
140 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 
141 node0 2023-03-08T04:33:36.157676Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
142 node0 2023-03-08T04:33:36.280098Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
143 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 
144 node0 2023-03-08T04:33:36.390249Z [init] [node/blockstorage.cpp:331] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
145 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) 
146 node0 2023-03-08T04:33:36.404146Z [init] [node/blockstorage.cpp:346] [LoadBlockIndexDB] Checking all blk files are present... 
147 node0 2023-03-08T04:33:36.416288Z [init] [validation.cpp:4432] [LoadBlockIndex] Initializing databases... 
148 node0 2023-03-08T04:33:36.459362Z [init] [flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x1000000 in blk00000.dat 
149 node0 2023-03-08T04:33:36.579730Z [init] [node/chainstate.cpp:124] [LoadChainstate] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
150 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 
151 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 
152 node0 2023-03-08T04:33:36.589283Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
153 node0 2023-03-08T04:33:36.602223Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
154 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 
155 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 
156 node0 2023-03-08T04:33:36.709887Z [init] [validation.cpp:5316] [MaybeRebalanceCaches] [snapshot] allocating all cache to the IBD chainstate 
157 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 
158 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 
159 node0 2023-03-08T04:33:36.925623Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
160 node0 2023-03-08T04:33:36.935842Z [init] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully 
161 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 
162 node0 2023-03-08T04:33:36.976133Z [init] [validation.cpp:4859] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinsdb cache to 8.0 MiB 
163 node0 2023-03-08T04:33:36.977592Z [init] [validation.cpp:4861] [ResizeCoinsCaches] [Chainstate [ibd] @ height -1 (null)] resized coinstip cache to 440.0 MiB 
164 node0 2023-03-08T04:33:36.994243Z [init] [noui.cpp:56] [noui_InitMessage] init message: Verifying blocks… 
165 node0 2023-03-08T04:33:37.003735Z [init] [init.cpp:1526] [AppInitMain]  block index             973ms 
166 node0 2023-03-08T04:33:37.120184Z [init] [init.cpp:1615] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
167 node0 2023-03-08T04:33:37.176589Z [loadblk] [util/thread.cpp:20] [TraceThread] loadblk thread start 
168 node0 2023-03-08T04:33:37.303188Z [loadblk] [validation.cpp:2821] [ConnectTip] [bench]   - Load block from disk: 67.60ms [0.07s (infms/blk)] 
169 node0 2023-03-08T04:33:37.344681Z [loadblk] [validationinterface.cpp:255] [BlockChecked] [validation] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
170 node0 2023-03-08T04:33:37.359966Z [loadblk] [validation.cpp:2837] [ConnectTip] [bench]   - Connect total: 64.73ms [0.06s (64.73ms/blk)] 
171 node0 2023-03-08T04:33:37.365292Z [loadblk] [validation.cpp:2846] [ConnectTip] [bench]   - Flush: 5.42ms [0.01s (5.42ms/blk)] 
172 node0 2023-03-08T04:33:37.367849Z [loadblk] [validation.cpp:2856] [ConnectTip] [bench]   - Writing chainstate: 2.58ms [0.00s (2.58ms/blk)] 
173 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) 
174 node0 2023-03-08T04:33:37.417058Z [loadblk] [validation.cpp:2872] [ConnectTip] [bench]   - Connect postprocess: 49.07ms [0.05s (49.07ms/blk)] 
175 node0 2023-03-08T04:33:37.418625Z [loadblk] [validation.cpp:2876] [ConnectTip] [bench] - Connect block: 189.40ms [0.19s (189.40ms/blk)] 
176 node0 2023-03-08T04:33:37.442143Z [loadblk] [txmempool.cpp:644] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
177 node0 2023-03-08T04:33:37.465583Z [loadblk] [validationinterface.cpp:232] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
178 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) 
179 node0 2023-03-08T04:33:37.503977Z [scheduler] [validationinterface.cpp:232] [operator()] [validation] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
180 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 
181 node0 2023-03-08T04:33:37.627201Z [loadblk] [kernel/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file from disk. Continuing anyway. 
182 node0 2023-03-08T04:33:37.631471Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
183 node0 2023-03-08T04:33:37.636774Z [init] [init.cpp:1702] [AppInitMain] block tree size = 1 
184 node0 2023-03-08T04:33:37.639881Z [init] [init.cpp:1714] [AppInitMain] nBestHeight = 0 
185 node0 2023-03-08T04:33:37.687986Z [init] [net.cpp:2169] [BindListenPort] Bound to 127.0.0.1:12164 
186 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. 
187 node0 2023-03-08T04:33:37.728781Z [init] [noui.cpp:56] [noui_InitMessage] init message: Starting network threads… 
188 node0 2023-03-08T04:33:37.770143Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
189 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) 
190 node0 2023-03-08T04:33:37.843300Z [init] [net.cpp:2375] [Start] DNS seeding disabled 
191 node0 2023-03-08T04:33:37.875528Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
192 node0 2023-03-08T04:33:37.954508Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
193 node0 2023-03-08T04:33:37.962532Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
194 node0 2023-03-08T04:33:37.967210Z [loadblk] [util/thread.cpp:22] [TraceThread] loadblk thread exit 
195 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 
196 node0 2023-03-08T04:33:37.992415Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
197 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 
198 node0 2023-03-08T04:33:38.050346Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
199 test  2023-03-08T04:33:38.100000Z TestFramework.node0 (DEBUG): RPC successfully started 
200 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 
201 node0 2023-03-08T04:33:38.104204Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
202 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 
203 node0 2023-03-08T04:33:38.113036Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
204 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 
205 node0 2023-03-08T04:33:38.139201Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
206 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 
207 node0 2023-03-08T04:33:38.198545Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
208 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 
209 node0 2023-03-08T04:33:38.204704Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
210 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 
211 node0 2023-03-08T04:33:38.210535Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
212 test  2023-03-08T04:33:38.260000Z TestFramework (INFO): Prepare blocks without sending them to the node 
213 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 
214 test  2023-03-08T04:33:38.357000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 1 
215 test  2023-03-08T04:33:38.357000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12175 should be started 
216 test  2023-03-08T04:33:38.357000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12175 outbound-full-relay 
217 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 
218 node0 2023-03-08T04:33:38.362283Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
219 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 
220 node0 2023-03-08T04:33:38.522445Z [httpworker.0] [net.cpp:2803] [CNode] [net] Added connection peer=0 
221 node0 2023-03-08T04:33:38.620249Z [httpworker.0] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=0 
222 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 
223 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
224 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) 
225 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) 
226 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
227 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
228 test  2023-03-08T04:33:38.667000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
229 node0 2023-03-08T04:33:38.760350Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=0 
230 node0 2023-03-08T04:33:38.782863Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=0 
231 test  2023-03-08T04:33:38.783000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
232 node0 2023-03-08T04:33:38.784558Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=0 
233 test  2023-03-08T04:33:38.785000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
234 node0 2023-03-08T04:33:38.804553Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=0 
235 test  2023-03-08T04:33:38.805000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
236 test  2023-03-08T04:33:38.808000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
237 node0 2023-03-08T04:33:38.820743Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=0 
238 test  2023-03-08T04:33:38.822000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
239 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 
240 node0 2023-03-08T04:33:38.860462Z [msghand] [timedata.cpp:57] [AddTimeData] [net] added time data, samples 2, offset +0 (+0 minutes) 
241 node0 2023-03-08T04:33:38.869913Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=0 
242 node0 2023-03-08T04:33:38.872434Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=0 
243 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) 
244 node0 2023-03-08T04:33:38.881594Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=0 
245 test  2023-03-08T04:33:38.882000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
246 node0 2023-03-08T04:33:38.896800Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=0 
247 test  2023-03-08T04:33:38.897000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=1bb06eba4cb67ee6) 
248 test  2023-03-08T04:33:38.897000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=1bb06eba4cb67ee6) 
249 node0 2023-03-08T04:33:38.938124Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getheaders (69 bytes) peer=0 
250 test  2023-03-08T04:33:38.939000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getheaders(locator=CBlockLocator(vHave=[7041830694386478471858881810674310864173988660927928131397671070347943617030]), stop=0000000000000000000000000000000000000000000000000000000000000000) 
251 node0 2023-03-08T04:33:38.943550Z [msghand] [net_processing.cpp:5428] [SendMessages] [net] initial getheaders (0) to peer=0 (startheight:-1) 
252 node0 2023-03-08T04:33:39.063559Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=0 
253 test  2023-03-08T04:33:39.065000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
254 node0 2023-03-08T04:33:39.069421Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=0 
255 node0 2023-03-08T04:33:39.076589Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=0 
256 node0 2023-03-08T04:33:39.082628Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=0 
257 node0 2023-03-08T04:33:39.084173Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=0 
258 test  2023-03-08T04:33:39.085000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
259 node0 2023-03-08T04:33:39.086280Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=0 
260 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) 
261 test  2023-03-08T04:33:39.125000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 2 
262 test  2023-03-08T04:33:39.126000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12174 should be started 
263 test  2023-03-08T04:33:39.126000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12174 outbound-full-relay 
264 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 
265 node0 2023-03-08T04:33:39.193670Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=0 
266 node0 2023-03-08T04:33:40.182417Z [httpworker.3] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
267 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 
268 node0 2023-03-08T04:34:16.953421Z [msghand] [validation.cpp:3832] [ProcessNewBlockHeaders] Synchronizing blockheaders, height: 1024 (~0.16%) 
269 node0 2023-03-08T04:34:16.960677Z [msghand] [net_processing.cpp:2760] [UpdatePeerStateForReceivedHeaders] [net] Protecting outbound peer=0 from eviction 
270 node0 2023-03-08T04:34:16.968677Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendheaders (0 bytes) peer=0 
271 node0 2023-03-08T04:34:16.975990Z [httpworker.3] [net.cpp:2803] [CNode] [net] Added connection peer=1 
272 node0 2023-03-08T04:34:17.026473Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 18f9c9ae8651e9aeb776ec51943c7fb4b813b1dedae262459d1915f69c345f52 (1) peer=0 
273 node0 2023-03-08T04:34:17.031283Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 (2) peer=0 
274 node0 2023-03-08T04:34:17.032878Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e (3) peer=0 
275 node0 2023-03-08T04:34:17.034043Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 (4) peer=0 
276 node0 2023-03-08T04:34:17.034682Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba (5) peer=0 
277 node0 2023-03-08T04:34:17.035761Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a (6) peer=0 
278 node0 2023-03-08T04:34:17.036375Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 (7) peer=0 
279 node0 2023-03-08T04:34:17.036989Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c85f8dbb1b755044218581116105a477603503f53725d61f2b5ee518971e8c0 (8) peer=0 
280 node0 2023-03-08T04:34:17.037626Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3525250b470c3e7759d1b62f4e70b48e5e08db11c45abc0b4b7bc084d7c58e5b (9) peer=0 
281 node0 2023-03-08T04:34:17.038227Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 2e13e49c2f95b6b17c8eece52ce971ce5610a9c8cd824b7be139fcbadae6d0b2 (10) peer=0 
282 node0 2023-03-08T04:34:17.038829Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 761977f25dff7cc5b9c0dac593f05383758147c9cb676afef410ddb2ea889495 (11) peer=0 
283 node0 2023-03-08T04:34:17.039432Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 5085f9b6a36365c466b6d84c96e74d7e135b245909bf37d2dc3169ae3fd8a358 (12) peer=0 
284 node0 2023-03-08T04:34:17.040050Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 7c7867082cd45356564ebb64ba8004c756d694015b9f13ecd2e4161f2083e041 (13) peer=0 
285 node0 2023-03-08T04:34:17.040657Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0db9883db92373bdb4c76b364dd8f884cef440ce7a199671e9d8772e4f51ec9e (14) peer=0 
286 node0 2023-03-08T04:34:17.041278Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 3efdfa1d6b4515648862589e3887ee60471334ce1b816af8ab4ef7319742d81e (15) peer=0 
287 node0 2023-03-08T04:34:17.041886Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0b71784b174e34d19f54b019952d9437840aa0eb458132ccb8cf288d744bb853 (16) peer=0 
288 node0 2023-03-08T04:34:17.050154Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (577 bytes) peer=0 
289 node0 2023-03-08T04:34:17.056789Z [httpworker.3] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=1 
290 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 
291 test  2023-03-08T04:34:17.061000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendheaders() 
292 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) 
293 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) 
294 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) 
295 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) 
296 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) 
297 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) 
298 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) 
299 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) 
300 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) 
301 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) 
302 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) 
303 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) 
304 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) 
305 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) 
306 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) 
307 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) 
308 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Connected & Listening: 0:0 
309 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) 
310 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) 
311 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_wtxidrelay() 
312 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_verack() 
313 test  2023-03-08T04:34:17.062000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_getaddr() 
314 node0 2023-03-08T04:34:17.067949Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
315 node0 2023-03-08T04:34:17.095135Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 734c86436d0ed4ca1fe836ee3f1c90e96a86550323a9ff089df5bf668a4a4419 peer=0 
316 node0 2023-03-08T04:34:17.314623Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364 (17) peer=0 
317 node0 2023-03-08T04:34:17.316018Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
318 test  2023-03-08T04:34:17.317000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=625833e9db593d27b8a8af896cb4b364116b36c3368c5e8e17006dcf5197f364)]) 
319 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) 
320 node0 2023-03-08T04:34:17.318461Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: version (111 bytes) peer=1 
321 node0 2023-03-08T04:34:17.320401Z [msghand] [net.cpp:2816] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=1 
322 test  2023-03-08T04:34:17.321000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_wtxidrelay() 
323 node0 2023-03-08T04:34:17.321425Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=1 
324 test  2023-03-08T04:34:17.322000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendaddrv2() 
325 node0 2023-03-08T04:34:17.325952Z [msghand] [net.cpp:2816] [PushMessage] [net] sending verack (0 bytes) peer=1 
326 test  2023-03-08T04:34:17.326000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_verack() 
327 node0 2023-03-08T04:34:17.327751Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getaddr (0 bytes) peer=1 
328 test  2023-03-08T04:34:17.328000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getaddr() 
329 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 
330 test  2023-03-08T04:34:17.337000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_ping(nonce=00000001) 
331 node0 2023-03-08T04:34:17.341056Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: wtxidrelay (0 bytes) peer=1 
332 node0 2023-03-08T04:34:17.342075Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
333 node0 2023-03-08T04:34:17.344183Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 47d5285c7f5699301d6ecd962f164721ce58e090db9e336a144454c317cea65e peer=0 
334 node0 2023-03-08T04:34:17.501499Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0 (18) peer=0 
335 test  2023-03-08T04:34:17.503000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=79ac1b3e2c638b26ef6a4b76e10234e08e12b89a9970831555505e7b6a047ca0)]) 
336 node0 2023-03-08T04:34:17.503060Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
337 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) 
338 node0 2023-03-08T04:34:17.505029Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: verack (0 bytes) peer=1 
339 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) 
340 node0 2023-03-08T04:34:17.507897Z [msghand] [net.cpp:2816] [PushMessage] [net] sending sendcmpct (9 bytes) peer=1 
341 test  2023-03-08T04:34:17.508000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_sendcmpct(announce=False, version=2) 
342 node0 2023-03-08T04:34:17.509531Z [msghand] [net.cpp:2816] [PushMessage] [net] sending ping (8 bytes) peer=1 
343 test  2023-03-08T04:34:17.510000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_ping(nonce=a55a24eb4e8e7e1a) 
344 test  2023-03-08T04:34:17.510000Z TestFramework.p2p (DEBUG): Send message to 0:0: msg_pong(nonce=a55a24eb4e8e7e1a) 
345 node0 2023-03-08T04:34:17.512518Z [msghand] [net.cpp:2816] [PushMessage] [net] sending feefilter (8 bytes) peer=1 
346 test  2023-03-08T04:34:17.514000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_feefilter(feerate=008bf035) 
347 node0 2023-03-08T04:34:17.514985Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
348 node0 2023-03-08T04:34:17.516419Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 41f66686c1a37265aeb205ab92a6552981da225fc727d7c82210cb5f4aab3640 peer=0 
349 node0 2023-03-08T04:34:17.672731Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b (19) peer=0 
350 node0 2023-03-08T04:34:17.674108Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
351 test  2023-03-08T04:34:17.675000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=1074503a013dc3a9ae7190a2b08c4c1482d65874e290a6441ab0e795f460e98b)]) 
352 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) 
353 node0 2023-03-08T04:34:17.676055Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: getaddr (0 bytes) peer=1 
354 node0 2023-03-08T04:34:17.676743Z [msghand] [net_processing.cpp:4561] [ProcessMessage] [net] Ignoring "getaddr" from outbound-full-relay connection. peer=1 
355 node0 2023-03-08T04:34:17.678892Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
356 node0 2023-03-08T04:34:17.680152Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 2bfe36c48afe10c2f32ae750a9a767500274757ff123080a3922ded6ca02cbba peer=0 
357 node0 2023-03-08T04:34:17.837257Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566 (20) peer=0 
358 node0 2023-03-08T04:34:17.838582Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
359 test  2023-03-08T04:34:17.839000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=0fd402980752136ea0226ab55539403461323acfa4676f0eb7d80cce906e5566)]) 
360 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) 
361 node0 2023-03-08T04:34:17.840527Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: ping (8 bytes) peer=1 
362 node0 2023-03-08T04:34:17.841295Z [msghand] [net.cpp:2816] [PushMessage] [net] sending pong (8 bytes) peer=1 
363 test  2023-03-08T04:34:17.843000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_pong(nonce=00000001) 
364 node0 2023-03-08T04:34:17.844040Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
365 node0 2023-03-08T04:34:17.845333Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 664f7832d34f38ece3f84aa834dacfc4c51890224fab9886f267c9add7484e2a peer=0 
366 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) 
367 test  2023-03-08T04:34:17.898000Z TestFramework.p2p (DEBUG): Listening for Bitcoin Node with id: 3 
368 test  2023-03-08T04:34:17.898000Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:12173 should be started 
369 test  2023-03-08T04:34:17.898000Z TestFramework.node0 (DEBUG): Connecting to 127.0.0.1:12173 outbound-full-relay 
370 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 
371 node0 2023-03-08T04:34:18.069483Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606 (21) peer=0 
372 node0 2023-03-08T04:34:18.070346Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
373 node0 2023-03-08T04:34:18.073460Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=addconnection user=__cookie__ 
374 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 
375 node0 2023-03-08T04:34:18.076877Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: block (144 bytes) peer=0 
376 node0 2023-03-08T04:34:18.078198Z [msghand] [net_processing.cpp:4528] [ProcessMessage] [net] received block 3ad1db4e6e77e01ec1376311b2606f4150c773bac3d315803eca8b3dfca6ef57 peer=0 
377 node0 2023-03-08T04:34:18.163118Z [httpworker.1] [net.cpp:2803] [CNode] [net] Added connection peer=2 
378 node0 2023-03-08T04:34:18.243066Z [msghand] [net_processing.cpp:5807] [SendMessages] [net] Requesting block 6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695 (22) peer=0 
379 node0 2023-03-08T04:34:18.243886Z [msghand] [net.cpp:2816] [PushMessage] [net] sending getdata (37 bytes) peer=0 
380 node0 2023-03-08T04:34:18.245300Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: pong (8 bytes) peer=1 
381 node0 2023-03-08T04:34:18.249221Z [msghand] [net_processing.cpp:3169] [ProcessMessage] [net] received: headers (82947 bytes) peer=1 
382 node0 2023-03-08T04:34:37.325285Z [httpworker.1] [net.cpp:2816] [PushMessage] [net] sending version (114 bytes) peer=2 
383 test  2023-03-08T04:35:17.908000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
384                                           test_function = lambda: self.is_connected
385                                   '''
386 test  2023-03-08T04:35:17.908000Z TestFramework (ERROR): Assertion failed 
387                                   Traceback (most recent call last):
388                                     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
389                                       self.run_test()
390                                     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
391                                       peers.append(node.add_outbound_p2p_connection(P2PStaller(stall_block), p2p_idx=id, connection_type="outbound-full-relay"))
392                                     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
393                                       p2p_conn.wait_for_connect()
394                                     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
395                                       wait_until_helper(test_function, timeout=timeout, lock=p2p_lock)
396                                     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
397                                       raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
398                                   AssertionError: Predicate ''''
399                                           test_function = lambda: self.is_connected
400                                   ''' not true after 60.0 seconds
401 test  2023-03-08T04:35:17.909000Z TestFramework (DEBUG): Closing down network thread 
402 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 
403 test  2023-03-08T04:35:27.925000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
404                                           wait_until_helper(lambda: not self.network_event_loop.is_running(), timeout=timeout)
405                                   '''
406 test  2023-03-08T04:35:30.950000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=752405439cea869d584044084502582bc209e4ef97e4bf3b8c2ba3958acaf606)]) 
407 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) 
408 test  2023-03-08T04:35:30.950000Z TestFramework.p2p (DEBUG): Received message from 0:0: msg_getdata(inv=[CInv(type=WitnessBlock hash=6c13148d31dbfdfb7a58920dfa054bb2ff50a54ebebedd604cb930a233901695)]) 
409 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) 
410...
411p2p_ibd_stalling.py                                    | ✖ Failed  | 126 s
412
413ALL                                                    | ✖ Failed  | 42880 s (accumulated) 
414Runtime: 11402 s

maflcko commented at 8:12 am on March 8, 2023: member

Are you running this via the ci system or directly?
maflcko commented at 8:13 am on March 8, 2023: member

Ah yes, CI doesn’t use --valgrind, so #27221 should make no difference.
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)
bitcoin deleted a comment on Mar 8, 2023
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.
maflcko commented at 10:33 am on March 8, 2023: member

Ok, see https://github.com/bitcoin/bitcoin/pull/27226
fanquake commented at 1:26 pm on March 10, 2023: member

Fixed by #27226.
fanquake closed this on Mar 10, 2023
bitcoin deleted a comment on Mar 12, 2023
bitcoin locked this on Mar 11, 2024

Contributors
fanquake maflcko

Labels
Bug Tests

Issue in p2p_ibd_stalling.py under Valgrind #27208

Issue in `p2p_ibd_stalling.py` under Valgrind #27208