test: interface_usdt_net.py failure under –valgrind #32374

issue fanquake openend this issue on April 29, 2025

fanquake commented at 11:33 am on April 29, 2025: member

Ubuntu 24.04.2 LTS (GNU/Linux 6.8.0-58-generic x86_64) gcc (Ubuntu 14.2.0-4ubuntu2~24.04) 14.2.0 valgrind-3.25.0

0cmake -B build -DWITH_USDT=ON
1cmake --build build
2./build/test/functional/test_runner.py --timeout-factor=9999 --valgrind interface_usdt_net.py

  0/root/ci_scratch/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0'
  1 test  2025-04-29T11:18:32.583000Z TestFramework (INFO): PRNG seed is: 3961365374660180483 
  2 test  2025-04-29T11:18:32.583000Z TestFramework (DEBUG): Setting up network thread 
  3 test  2025-04-29T11:18:32.584000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0 
  4 test  2025-04-29T11:18:32.584000Z TestFramework (DEBUG): Creating cache directory /root/ci_scratch/build/test/cache/node0 
  5 test  2025-04-29T11:18:32.585000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
  6 test  2025-04-29T11:18:32.842000Z TestFramework.node0 (DEBUG): RPC successfully started 
  7 test  2025-04-29T11:18:32.844000Z TestFramework.node0 (DEBUG): RPC successfully started 
  8 test  2025-04-29T11:18:33.046000Z TestFramework.node0 (DEBUG): Stopping node 
  9 test  2025-04-29T11:18:33.198000Z TestFramework.node0 (DEBUG): Node stopped 
 10 test  2025-04-29T11:18:33.200000Z TestFramework (DEBUG): Copy cache directory /root/ci_scratch/build/test/cache/node0 to node 0 
 11 test  2025-04-29T11:18:33.245000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 12 node0 2025-04-29T11:18:36.097251Z [init] [init/common.cpp:151] [LogPackageVersion] Bitcoin Core version v29.99.0-c5e44a043563 (release build) 
 13 node0 2025-04-29T11:18:36.105631Z [init] [init.cpp:722] [InitParameterInteraction] parameter interaction: -bind set -> setting -listen=1 
 14 node0 2025-04-29T11:18:36.336642Z [init] [kernel/context.cpp:20] [operator()] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 15 node0 2025-04-29T11:18:36.633915Z [init] [random.cpp:111] [ReportHardwareRand] Using RdSeed as an additional entropy source 
 16 node0 2025-04-29T11:18:36.634205Z [init] [random.cpp:114] [ReportHardwareRand] Using RdRand as an additional entropy source 
 17 node0 2025-04-29T11:18:36.957186Z [init] [init/common.cpp:119] [StartLogging] Default data directory /root/.bitcoin 
 18 node0 2025-04-29T11:18:36.959061Z [init] [init/common.cpp:120] [StartLogging] Using data directory /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest 
 19 node0 2025-04-29T11:18:36.960101Z [init] [init/common.cpp:129] [StartLogging] Config file: /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/bitcoin.conf 
 20 node0 2025-04-29T11:18:36.963467Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: regtest="1" 
 21 node0 2025-04-29T11:18:36.965363Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 22 node0 2025-04-29T11:18:36.965494Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 23 node0 2025-04-29T11:18:36.965643Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] deprecatedrpc="create_bdb" 
 24 node0 2025-04-29T11:18:36.965767Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 25 node0 2025-04-29T11:18:36.965873Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 26 node0 2025-04-29T11:18:36.966446Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 27 node0 2025-04-29T11:18:36.966569Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 28 node0 2025-04-29T11:18:36.966697Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 29 node0 2025-04-29T11:18:36.966802Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 30 node0 2025-04-29T11:18:36.967011Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] maxconnections="94" 
 31 node0 2025-04-29T11:18:36.967152Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 32 node0 2025-04-29T11:18:36.967262Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999" 
 33 node0 2025-04-29T11:18:36.967370Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] port="11000" 
 34 node0 2025-04-29T11:18:36.967478Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 35 node0 2025-04-29T11:18:36.967588Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1" 
 36 node0 2025-04-29T11:18:36.967721Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcport="16000" 
 37 node0 2025-04-29T11:18:36.968178Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcservertimeout="99000" 
 38 node0 2025-04-29T11:18:36.968304Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] server="1" 
 39 node0 2025-04-29T11:18:36.968412Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 40 node0 2025-04-29T11:18:36.968518Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 41 node0 2025-04-29T11:18:36.969036Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: datadir="/tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0" 
 42 node0 2025-04-29T11:18:36.969364Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debug="" 
 43 node0 2025-04-29T11:18:36.969489Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 44 node0 2025-04-29T11:18:36.969597Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 45 node0 2025-04-29T11:18:36.969725Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="rand" 
 46 node0 2025-04-29T11:18:36.969840Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: disablewallet="" 
 47 node0 2025-04-29T11:18:36.969960Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: loglevel="trace" 
 48 node0 2025-04-29T11:18:36.970069Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 49 node0 2025-04-29T11:18:36.970190Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logthreadnames="" 
 50 node0 2025-04-29T11:18:36.970293Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logtimemicros="" 
 51 node0 2025-04-29T11:18:36.970398Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: maxconnections="32" 
 52 node0 2025-04-29T11:18:36.970504Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 53 node0 2025-04-29T11:18:36.970605Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: v2transport="0" 
 54 node0 2025-04-29T11:18:36.972402Z [init] [init.cpp:1356] [AppInitMain] Using at most 32 automatic connections (1024 file descriptors available) 
 55 node0 2025-04-29T11:18:36.999851Z [init] [wallet/init.cpp:120] [Construct] Wallet disabled! 
 56 node0 2025-04-29T11:18:38.109153Z [init] [httpserver.cpp:239] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 57 node0 2025-04-29T11:18:38.128450Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address ::1 port 16000 
 58 node0 2025-04-29T11:18:38.144722Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 16000 
 59 node0 2025-04-29T11:18:38.146313Z [init] [httpserver.cpp:477] [InitHTTPServer] [http] Initialized HTTP server 
 60 node0 2025-04-29T11:18:38.148475Z [init] [httpserver.cpp:479] [InitHTTPServer] [http] creating work queue of depth 64 
 61 node0 2025-04-29T11:18:38.150171Z [init] [rpc/server.cpp:282] [StartRPC] [rpc] Starting RPC 
 62 node0 2025-04-29T11:18:38.151231Z [init] [httprpc.cpp:364] [StartHTTPRPC] [rpc] Starting HTTP RPC server 
 63 node0 2025-04-29T11:18:38.168763Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start 
 64 node0 2025-04-29T11:18:38.177590Z [init] [rpc/request.cpp:138] [GenerateAuthCookie] Generated RPC authentication cookie /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/.cookie 
 65 node0 2025-04-29T11:18:38.178436Z [init] [rpc/request.cpp:139] [GenerateAuthCookie] Permissions used for cookie: rw------- 
 66 node0 2025-04-29T11:18:38.179783Z [init] [httprpc.cpp:314] [InitRPCAuthentication] Using random cookie authentication. 
 67 node0 2025-04-29T11:18:38.183825Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1) 
 68 node0 2025-04-29T11:18:38.186296Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0) 
 69 node0 2025-04-29T11:18:38.188282Z [init] [httpserver.cpp:502] [StartHTTPServer] Starting HTTP server with 16 worker threads 
 70 node0 2025-04-29T11:18:38.456022Z [init] [init.cpp:1477] [AppInitMain] Using /16 prefix for IP bucketing 
 71 node0 2025-04-29T11:18:38.459956Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading P2P addresses… 
 72 node0 2025-04-29T11:18:38.505086Z [init] [addrdb.cpp:206] [LoadAddrman] Creating peers.dat because the file was not found ("/tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/peers.dat") 
 73 node0 2025-04-29T11:18:38.526349Z [http] [httpserver.cpp:352] [ThreadHTTP] [http] Entering http event loop 
 74 node0 2025-04-29T11:18:38.620591Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56180 
 75 node0 2025-04-29T11:18:38.676905Z [httpworker.8] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 76 node0 2025-04-29T11:18:38.715210Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading banlist… 
 77 node0 2025-04-29T11:18:38.716049Z [init] [banman.cpp:42] [LoadBanlist] Recreating the banlist database 
 78 node0 2025-04-29T11:18:38.783159Z [init] [banman.cpp:68] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  60ms 
 79 node0 2025-04-29T11:18:38.794771Z [init] [net.cpp:2426] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false 
 80 node0 2025-04-29T11:18:38.804540Z [init] [net.cpp:3199] [SetNetworkActive] SetNetworkActive: true 
 81 node0 2025-04-29T11:18:38.820654Z [init] [policy/fees.cpp:563] [CBlockPolicyEstimator] /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/fee_estimates.dat is not found. Continue anyway. 
 82 node0 2025-04-29T11:18:38.835593Z [init] [init.cpp:1673] [AppInitMain] Cache configuration: 
 83 node0 2025-04-29T11:18:38.839026Z [init] [init.cpp:1674] [AppInitMain] * Using 2.0 MiB for block index database 
 84 node0 2025-04-29T11:18:38.841049Z [init] [init.cpp:1682] [AppInitMain] * Using 8.0 MiB for chain state database 
 85 node0 2025-04-29T11:18:38.850586Z [init] [init.cpp:1245] [InitAndLoadChainstate] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 
 86 node0 2025-04-29T11:18:38.854553Z [init] [checkqueue.h:147] [CCheckQueue] Script verification uses 15 additional threads 
 87 node0 2025-04-29T11:18:39.104394Z [init] [node/blockstorage.cpp:1154] [InitBlocksdirXorKey] Using obfuscation key for blocksdir *.dat files (/tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/blocks): 'bba0fb6fb6ea7766' 
 88 node0 2025-04-29T11:18:39.112051Z [init] [dbwrapper.cpp:235] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/blocks/index 
 89 node0 2025-04-29T11:18:39.251986Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56188 
 90 node0 2025-04-29T11:18:39.256674Z [httpworker.12] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 91 node0 2025-04-29T11:18:39.269032Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully 
 92 node0 2025-04-29T11:18:39.274643Z [init] [dbwrapper.cpp:268] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/blocks/index: 0000000000000000 
 93 node0 2025-04-29T11:18:39.297762Z [init] [script/sigcache.cpp:35] [SignatureCache] Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements 
 94 node0 2025-04-29T11:18:39.316456Z [init] [validation.cpp:2140] [ValidationCache] Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements 
 95 node0 2025-04-29T11:18:39.319018Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading block index… 
 96 node0 2025-04-29T11:18:39.319818Z [init] [node/chainstate.cpp:150] [LoadChainstate] Validating signatures for all blocks. 
 97 node0 2025-04-29T11:18:39.320483Z [init] [node/chainstate.cpp:152] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 98 node0 2025-04-29T11:18:39.387297Z [init] [node/blockstorage.cpp:508] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
 99 node0 2025-04-29T11:18:39.396505Z [init] [node/blockstorage.cpp:512] [LoadBlockIndexDB] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=200, size=52530, heights=0...199, time=2011-02-02...2011-02-02) 
100 node0 2025-04-29T11:18:39.397605Z [init] [node/blockstorage.cpp:523] [LoadBlockIndexDB] Checking all blk files are present... 
101 node0 2025-04-29T11:18:39.418276Z [init] [node/chainstate.cpp:87] [CompleteChainstateInitialization] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
102 node0 2025-04-29T11:18:39.420676Z [init] [dbwrapper.cpp:235] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/chainstate 
103 node0 2025-04-29T11:18:39.432880Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully 
104 node0 2025-04-29T11:18:39.435256Z [init] [dbwrapper.cpp:268] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/node0/regtest/chainstate: 6f92fc877cf4699c 
105 node0 2025-04-29T11:18:39.452040Z [init] [validation.cpp:4719] [LoadChainTip] Loaded best chain: hashBestChain=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c height=199 date=2011-02-02T23:17:17Z progress=1.000000 
106 node0 2025-04-29T11:18:39.458142Z [init] [noui.cpp:57] [noui_InitMessage] init message: Verifying blocks… 
107 node0 2025-04-29T11:18:39.462490Z [init] [validation.cpp:4762] [VerifyDB] Verifying last 6 blocks at level 3 
108 node0 2025-04-29T11:18:39.463138Z [init] [validation.cpp:4771] [VerifyDB] Verification progress: 0% 
109 node0 2025-04-29T11:18:39.502551Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 16% 
110 node0 2025-04-29T11:18:39.507494Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 33% 
111 node0 2025-04-29T11:18:39.511317Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 50% 
112 node0 2025-04-29T11:18:39.513636Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 66% 
113 node0 2025-04-29T11:18:39.516569Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 83% 
114 node0 2025-04-29T11:18:39.519193Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 99% 
115 node0 2025-04-29T11:18:39.519738Z [init] [validation.cpp:4873] [VerifyDB] Verification: No coin database inconsistencies in last 6 blocks (6 transactions) 
116 node0 2025-04-29T11:18:39.522169Z [init] [init.cpp:1330] [InitAndLoadChainstate] Block index and chainstate loaded 
117 node0 2025-04-29T11:18:39.529187Z [init] [init.cpp:1779] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
118 node0 2025-04-29T11:18:39.558905Z [init] [init.cpp:1889] [AppInitMain] block tree size = 200 
119 node0 2025-04-29T11:18:39.560014Z [init] [init.cpp:1902] [AppInitMain] nBestHeight = 199 
120 node0 2025-04-29T11:18:39.582910Z [init] [net.cpp:3172] [BindListenPort] Bound to 127.0.0.1:11000 
121 node0 2025-04-29T11:18:39.590514Z [init] [noui.cpp:57] [noui_InitMessage] init message: Starting network threads… 
122 node0 2025-04-29T11:18:39.621345Z [init] [net.cpp:3362] [Start] DNS seeding disabled 
123 node0 2025-04-29T11:18:39.665227Z [init] [noui.cpp:57] [noui_InitMessage] init message: Done loading 
124 node0 2025-04-29T11:18:39.670899Z [initload] [util/thread.cpp:20] [TraceThread] initload thread start 
125 node0 2025-04-29T11:18:39.693254Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
126 node0 2025-04-29T11:18:39.699831Z [initload] [node/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file. Continuing anyway. 
127 node0 2025-04-29T11:18:39.700887Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
128 node0 2025-04-29T11:18:39.715287Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
129 node0 2025-04-29T11:18:39.715532Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
130 node0 2025-04-29T11:18:39.718248Z [initload] [util/thread.cpp:22] [TraceThread] initload thread exit 
131 node0 2025-04-29T11:18:39.727452Z [httpworker.5] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
132 node0 2025-04-29T11:18:39.761539Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
133 node0 2025-04-29T11:18:39.762383Z [httpworker.0] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
134 test  2025-04-29T11:18:39.824000Z TestFramework.node0 (DEBUG): RPC successfully started 
135 node0 2025-04-29T11:18:39.825373Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
136 node0 2025-04-29T11:18:39.830188Z [httpworker.14] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
137 test  2025-04-29T11:18:39.879000Z TestFramework (DEBUG): Generate a block with current time 
138 test  2025-04-29T11:18:39.879000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress` 
139 node0 2025-04-29T11:18:39.880491Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
140 node0 2025-04-29T11:18:39.884083Z [httpworker.3] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__ 
141 node0 2025-04-29T11:18:39.956014Z [httpworker.3] [node/miner.cpp:168] [CreateNewBlock] CreateNewBlock(): block weight: 904 txs: 0 fees: 0 sigops 400 
142 node0 2025-04-29T11:18:39.969090Z [httpworker.3] [validation.cpp:2524] [ConnectBlock] [bench]     - Sanity checks: 0.88ms [0.00s (0.88ms/blk)] 
143 node0 2025-04-29T11:18:39.975541Z [httpworker.3] [validation.cpp:2626] [ConnectBlock] [bench]     - Fork checks: 8.22ms [0.01s (8.22ms/blk)] 
144 node0 2025-04-29T11:18:39.983532Z [httpworker.3] [validation.cpp:2718] [ConnectBlock] [bench]       - Connect 1 transactions: 6.40ms (6.400ms/tx, 0.000ms/txin) [0.01s (6.40ms/blk)] 
145 node0 2025-04-29T11:18:39.987294Z [httpworker.3] [validation.cpp:2740] [ConnectBlock] [bench]     - Verify 0 txins: 10.17ms (0.000ms/txin) [0.01s (10.17ms/blk)] 
146 node0 2025-04-29T11:18:39.991337Z [httpworker.3] [node/miner.cpp:183] [CreateNewBlock] [bench] CreateNewBlock() packages: 6.10ms (0 packages, 0 updated descendants), validity: 49.97ms (total 56.08ms) 
147 node0 2025-04-29T11:18:39.999455Z [httpworker.3] [validation.cpp:4421] [AcceptBlockHeader] [validation] Saw new header hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf height=200 
148 node0 2025-04-29T11:18:40.029510Z [httpworker.3] [validation.cpp:3187] [ConnectTip] [bench]   - Using cached block 
149 node0 2025-04-29T11:18:40.030315Z [httpworker.3] [validation.cpp:3196] [ConnectTip] [bench]   - Load block from disk: 0.69ms 
150 node0 2025-04-29T11:18:40.031000Z [httpworker.3] [validation.cpp:2524] [ConnectBlock] [bench]     - Sanity checks: 0.01ms [0.00s (0.44ms/blk)] 
151 node0 2025-04-29T11:18:40.031290Z [httpworker.3] [validation.cpp:2626] [ConnectBlock] [bench]     - Fork checks: 0.31ms [0.01s (4.26ms/blk)] 
152 node0 2025-04-29T11:18:40.031499Z [httpworker.3] [validation.cpp:2718] [ConnectBlock] [bench]       - Connect 1 transactions: 0.20ms (0.200ms/tx, 0.000ms/txin) [0.01s (3.30ms/blk)] 
153 node0 2025-04-29T11:18:40.031691Z [httpworker.3] [validation.cpp:2740] [ConnectBlock] [bench]     - Verify 0 txins: 0.39ms (0.000ms/txin) [0.01s (5.28ms/blk)] 
154 node0 2025-04-29T11:18:40.038082Z [httpworker.3] [validation.cpp:2756] [ConnectBlock] [bench]     - Write undo data: 5.80ms [0.01s (2.90ms/blk)] 
155 node0 2025-04-29T11:18:40.039358Z [httpworker.3] [validation.cpp:2771] [ConnectBlock] [bench]     - Index writing: 1.39ms [0.00s (0.70ms/blk)] 
156 node0 2025-04-29T11:18:40.042890Z [httpworker.3] [validationinterface.cpp:249] [BlockChecked] [validation] BlockChecked: block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf state=Valid 
157 node0 2025-04-29T11:18:40.045771Z [httpworker.3] [validation.cpp:3213] [ConnectTip] [bench]   - Connect total: 15.21ms [0.02s (7.60ms/blk)] 
158 node0 2025-04-29T11:18:40.052408Z [httpworker.3] [validation.cpp:3222] [ConnectTip] [bench]   - Flush: 6.76ms [0.01s (3.38ms/blk)] 
159 node0 2025-04-29T11:18:40.053493Z [httpworker.3] [validation.cpp:3232] [ConnectTip] [bench]   - Writing chainstate: 1.08ms [0.00s (0.54ms/blk)] 
160 node0 2025-04-29T11:18:40.060179Z [httpworker.3] [validationinterface.cpp:225] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=200 txs removed=0 
161 node0 2025-04-29T11:18:40.063752Z [httpworker.3] [validation.cpp:2038] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false) 
162 node0 2025-04-29T11:18:40.069717Z [httpworker.3] [validation.cpp:2998] [UpdateTipLog] UpdateTip: new best=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf height=200 version=0x30000000 log2_work=8.651052 tx=201 date='2025-04-29T11:18:39Z' progress=1.000000 cache=0.3MiB(1txo) 
163 node0 2025-04-29T11:18:40.071460Z [httpworker.3] [validation.cpp:3248] [ConnectTip] [bench]   - Connect postprocess: 17.94ms [0.02s (8.97ms/blk)] 
164 node0 2025-04-29T11:18:40.072213Z [httpworker.3] [validation.cpp:3252] [ConnectTip] [bench] - Connect block: 41.68ms [0.04s (20.84ms/blk)] 
165 node0 2025-04-29T11:18:40.076785Z [httpworker.3] [txmempool.cpp:700] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
166 node0 2025-04-29T11:18:40.083095Z [httpworker.3] [validationinterface.cpp:215] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf block height=200 
167 node0 2025-04-29T11:18:40.088401Z [httpworker.3] [validationinterface.cpp:179] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf fork block hash=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c (in IBD=false) 
168 node0 2025-04-29T11:18:40.092373Z [httpworker.3] [validationinterface.cpp:187] [ActiveTipChange] [validation] ActiveTipChange: new block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf block height=200 
169 node0 2025-04-29T11:18:40.110192Z [scheduler] [validationinterface.cpp:225] [operator()] [validation] MempoolTransactionsRemovedForBlock: block height=200 txs removed=0 
170 node0 2025-04-29T11:18:40.128855Z [scheduler] [policy/fees.cpp:709] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
171 node0 2025-04-29T11:18:40.135725Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
172 node0 2025-04-29T11:18:40.137281Z [httpworker.8] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
173 node0 2025-04-29T11:18:40.153720Z [scheduler] [validationinterface.cpp:215] [operator()] [validation] BlockConnected: block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf block height=200 
174 node0 2025-04-29T11:18:40.175129Z [scheduler] [validationinterface.cpp:179] [operator()] [validation] UpdatedBlockTip: new block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf fork block hash=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c (in IBD=false) 
175 node0 2025-04-29T11:18:40.184544Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
176 node0 2025-04-29T11:18:40.186776Z [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=submitblock user=__cookie__ 
177 node0 2025-04-29T11:18:40.232385Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
178 node0 2025-04-29T11:18:40.233363Z [httpworker.2] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
179 node0 2025-04-29T11:18:40.239458Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
180 node0 2025-04-29T11:18:40.240195Z [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
181 node0 2025-04-29T11:18:40.243359Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
182 node0 2025-04-29T11:18:40.244314Z [httpworker.4] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
183 node0 2025-04-29T11:18:40.253800Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:56196 
184 node0 2025-04-29T11:18:40.254891Z [httpworker.10] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
185 test  2025-04-29T11:18:40.263000Z TestFramework (INFO): hook into the net:inbound_message and net:outbound_message tracepoints 
186 test  2025-04-29T11:18:41.320000Z TestFramework (INFO): connect a P2P test node to our bitcoind node 
187 test  2025-04-29T11:18:41.321000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:11000 
188 test  2025-04-29T11:18:41.321000Z TestFramework.p2p (DEBUG): Connected: us=127.0.0.1:41596, them=127.0.0.1:11000 
189 test  2025-04-29T11:18:41.322000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11000: msg_version(nVersion=70016 nServices=9 nTime=Tue Apr 29 11:18:41 2025 addrTo=CAddress(nServices=1 net=IPv4 addr=127.0.0.1 port=11000) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xB7DD25BB6D9421D3 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1) 
190 node0 2025-04-29T11:18:41.371553Z [net] [net.cpp:3833] [CNode] [net] Added connection peer=0 
191 node0 2025-04-29T11:18:41.377182Z [net] [net.cpp:1854] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:41596 accepted 
192 test  2025-04-29T11:18:42.141000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:11000 
193 test  2025-04-29T11:18:42.173000Z TestFramework (ERROR): Assertion failed 
194                                   Traceback (most recent call last):
195                                     File "/root/ci_scratch/test/functional/test_framework/test_framework.py", line 183, in main
196                                       self.run_test()
197                                     File "/root/ci_scratch/build/test/functional/interface_usdt_net.py", line 259, in run_test
198                                       self.p2p_message_tracepoint_test()
199                                     File "/root/ci_scratch/build/test/functional/interface_usdt_net.py", line 327, in p2p_message_tracepoint_test
200                                       self.nodes[0].add_p2p_connection(test_node)
201                                     File "/root/ci_scratch/test/functional/test_framework/test_node.py", line 736, in add_p2p_connection
202                                       p2p_conn.wait_for_verack()
203                                     File "/root/ci_scratch/test/functional/test_framework/p2p.py", line 692, in wait_for_verack
204                                       self.wait_until(test_function, timeout=timeout)
205                                     File "/root/ci_scratch/test/functional/test_framework/p2p.py", line 601, in wait_until
206                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
207                                     File "/root/ci_scratch/test/functional/test_framework/util.py", line 311, in wait_until_helper_internal
208                                       if predicate():
209                                          ^^^^^^^^^^^
210                                     File "/root/ci_scratch/test/functional/test_framework/p2p.py", line 598, in test_function
211                                       assert self.is_connected
212                                              ^^^^^^^^^^^^^^^^^
213                                   AssertionError
214 test  2025-04-29T11:18:42.176000Z TestFramework (DEBUG): Closing down network thread 
215 test  2025-04-29T11:18:42.227000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later. 
216 test  2025-04-29T11:18:42.227000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0 
217 test  2025-04-29T11:18:42.227000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0/test_framework.log 
218 test  2025-04-29T11:18:42.227000Z TestFramework (ERROR): 
219 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): Hint: Call /root/ci_scratch/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0' to consolidate all logs 
220 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): 
221 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log. 
222 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues 
223 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): 
224
225 node0 stderr ==1145996== 
226==1145996== Process terminating with default action of signal 5 (SIGTRAP)
227==1145996==    at 0x41EF0E6: ~basic_string (basic_string.h:809)
228==1145996==    by 0x41EF0E6: (anonymous namespace)::PeerManagerImpl::ProcessMessages(CNode*, std::atomic<bool>&) (net_processing.cpp:5006)
229==1145996==    by 0x41A782D: CConnman::ThreadMessageHandler() (net.cpp:3054)
230==1145996==    by 0x4877F0E: operator() (std_function.h:591)
231==1145996==    by 0x4877F0E: util::TraceThread(std::basic_string_view<char, std::char_traits<char> >, std::function<void ()>) (thread.cpp:21)
232==1145996==    by 0x4199DC6: __invoke_impl<void, void (*)(std::basic_string_view<char>, std::function<void()>), char const*, CConnman::Start(CScheduler&, const Options&)::<lambda()> > (invoke.h:61)
233==1145996==    by 0x4199DC6: __invoke<void (*)(std::basic_string_view<char>, std::function<void()>), char const*, CConnman::Start(CScheduler&, const Options&)::<lambda()> > (invoke.h:96)
234==1145996==    by 0x4199DC6: _M_invoke<0, 1, 2> (std_thread.h:301)
235==1145996==    by 0x4199DC6: operator() (std_thread.h:308)
236==1145996==    by 0x4199DC6: std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(std::basic_string_view<char, std::char_traits<char> >, std::function<void ()>), char const*, CConnman::Start(CScheduler&, CConnman::Options const&)::{lambda()#5}> > >::_M_run() (std_thread.h:253)
237==1145996==    by 0x576CDB3: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.33)
238==1145996==    by 0x5AB1AA3: start_thread (pthread_create.c:447)
239==1145996==    by 0x5B3EA33: clone (clone.S:100)

https://github.com/gcc-mirror/gcc/blob/04696df09633baf97cdbbdd6e9929b9d472161d3/libstdc%2B%2B-v3/include/bits/basic_string.h#L809.

willcl-ark commented at 12:08 pm on April 30, 2025: member

I am able to replicate this on NixOS

  0bitcoin on  master [$?⇡] via △ v3.30.5 via 🐍 v3.12.7 via ❄️  impure (nix-shell-env)
  1❯ just build -DWITH_USDT=ON
  2configure running
  3configure complete
  4build running
  5build complete
  6
  7bitcoin on  master [$?⇡] via △ v3.30.5 via 🐍 v3.12.7 via ❄️  impure (nix-shell-env) took 41s
  8❯ sudo -E PYTHONPATH="/nix/store/nql0w8in8bj1i3f0xgpxr40hx2gy2lgg-bcc-0.31.0/lib/python3.12/site-packages:/nix/store/bymayrdmvq8ahkhrlcw2akjsyif8qv1g-python3.12-netaddr-1.3.0/lib/python3.12/site-packages:/nix/store/px2nj16i5gc3d4mnw5l1nclfdxhry61p-python3-3.12.7/lib/python3.12/site-packages:/nix/store/sfkwdrfqp24wyssnfc6wzrrq94jhxy8i-codespell-2.3.0/lib/python3.12/site-packages:/nix/store/xn648kkidbibpmbm97dgw4520jb05h4d-python3.12-flake8-7.1.1/lib/python3.12/site-packages:/nix/store/v0izs2ffiidns6rnvjzyg0qs8j0qcg4f-python3.12-mccabe-0.7.0/lib/python3.12/site-packages:/nix/store/9xhj6rpg5cimg5q9q2fhx6h35phpdvg4-python3.12-pycodestyle-2.12.0/lib/python3.12/site-packages:/nix/store/zz975r9r1c35w1vsijx066k4zpk6wvlw-python3.12-pyflakes-3.2.0/lib/python3.12/site-packages:/nix/store/c2yzzj4kry2c8lfrvcgzd3rrywmmcb2w-lief-0.15.1-py/lib/python3.12/site-packages:/nix/store/bzd6x228spgh76jwlh97z2z7fcjkkhhq-python3.12-mypy-1.11.2/lib/python3.12/site-packages:/nix/store/aqjkz6gkjcscafk3hrkv6g6mvvskq2lz-python3.12-mypy-extensions-1.0.0/lib/python3.12/site-packages:/nix/store/rm2lnxxw22l35n5wv579xl6prpb0lggz-python3.12-typing-extensions-4.12.2/lib/python3.12/site-packages:/nix/store/cshqmr02fi91pv7s78djpzpf95nrzwxk-python3.12-pyzmq-26.2.0/lib/python3.12/site-packages:/nix/store/a7dr8zjwjadyw9ngcn74incvkxqwkyha-python3.12-vulture-2.13/lib/python3.12/site-packages:/nix/store/famwj4wka071vad5k5rhnvh8jfdishif-libselinux-3.7/lib/python3.12/site-packages:/nix/store/plgmjfks0wb6v307dixvvcq5w4vldjzz-uv-0.4.30/lib/python3.12/site-packages:/nix/store/nql0w8in8bj1i3f0xgpxr40hx2gy2lgg-bcc-0.31.0/lib/python3.12/site-packages/bcc-0.31.0-py3.12.egg" ./build/test/functional/test_runner.py --timeout-factor=9999 --valgrind interface_usdt_net.py
  9Temporary test directory at /tmp/test_runner_₿_🏃_20250430_130404
 10Remaining jobs: [interface_usdt_net.py]
 111/1 - interface_usdt_net.py failed, Duration: 9 s
 12
 13stdout:
 142025-04-30T12:04:04.799000Z TestFramework (INFO): PRNG seed is: 4383659148042625286
 152025-04-30T12:04:04.799000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
 162025-04-30T12:04:11.349000Z TestFramework (INFO): hook into the net:inbound_message and net:outbound_message tracepoints
 172025-04-30T12:04:12.884000Z TestFramework (INFO): connect a P2P test node to our bitcoind node
 182025-04-30T12:04:13.485000Z TestFramework (ERROR): Assertion failed
 19Traceback (most recent call last):
 20  File "/home/will/src/core/bitcoin/test/functional/test_framework/test_framework.py", line 183, in main
 21    self.run_test()
 22  File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 259, in run_test
 23    self.p2p_message_tracepoint_test()
 24  File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 327, in p2p_message_tracepoint_test
 25    self.nodes[0].add_p2p_connection(test_node)
 26  File "/home/will/src/core/bitcoin/test/functional/test_framework/test_node.py", line 736, in add_p2p_connection
 27    p2p_conn.wait_for_verack()
 28  File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 692, in wait_for_verack
 29    self.wait_until(test_function, timeout=timeout)
 30  File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 601, in wait_until
 31    wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
 32  File "/home/will/src/core/bitcoin/test/functional/test_framework/util.py", line 311, in wait_until_helper_internal
 33    if predicate():
 34       ^^^^^^^^^^^
 35  File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 598, in test_function
 36    assert self.is_connected
 37           ^^^^^^^^^^^^^^^^^
 38AssertionError
 392025-04-30T12:04:13.536000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
 402025-04-30T12:04:13.536000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
 412025-04-30T12:04:13.536000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/test_framework.log
 422025-04-30T12:04:13.536000Z TestFramework (ERROR):
 432025-04-30T12:04:13.537000Z TestFramework (ERROR): Hint: Call /home/will/src/core/bitcoin/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0' to consolidate all logs
 442025-04-30T12:04:13.537000Z TestFramework (ERROR):
 452025-04-30T12:04:13.537000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
 462025-04-30T12:04:13.537000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
 472025-04-30T12:04:13.537000Z TestFramework (ERROR):
 48
 49
 50stderr:
 51[node 0] Cleaning up leftover process
 52
 53
 54
 55TEST                  | STATUS    | DURATION
 56
 57interface_usdt_net.py | ✖ Failed  | 9 s
 58
 59ALL                   | ✖ Failed  | 9 s (accumulated)
 60Runtime: 9 s
 61
 62
 63bitcoin on  master [$?⇡] via △ v3.30.5 via 🐍 v3.12.7 via ❄️  impure (nix-shell-env) took 9s
 64❯ sudo /home/will/src/core/bitcoin/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0'
 65 test  2025-04-30T12:04:04.799000Z TestFramework (INFO): PRNG seed is: 4383659148042625286
 66 test  2025-04-30T12:04:04.799000Z TestFramework (DEBUG): Setting up network thread
 67 test  2025-04-30T12:04:04.799000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
 68 test  2025-04-30T12:04:04.799000Z TestFramework (DEBUG): Creating cache directory /home/will/src/core/bitcoin/build/test/cache/node0
 69 test  2025-04-30T12:04:04.800000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
 70 test  2025-04-30T12:04:05.052000Z TestFramework.node0 (DEBUG): RPC successfully started
 71 test  2025-04-30T12:04:05.053000Z TestFramework.node0 (DEBUG): RPC successfully started
 72 test  2025-04-30T12:04:05.116000Z TestFramework.node0 (DEBUG): Stopping node
 73 test  2025-04-30T12:04:05.267000Z TestFramework.node0 (DEBUG): Node stopped
 74 test  2025-04-30T12:04:05.267000Z TestFramework (DEBUG): Copy cache directory /home/will/src/core/bitcoin/build/test/cache/node0 to node 0
 75 test  2025-04-30T12:04:05.277000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
 76 node0 2025-04-30T12:04:07.780089Z [init] [init/common.cpp:151] [LogPackageVersion] Bitcoin Core version v29.99.0-14b8dfb2bd5e (release build)
 77 node0 2025-04-30T12:04:07.788485Z [init] [init.cpp:722] [InitParameterInteraction] parameter interaction: -bind set -> setting -listen=1
 78 node0 2025-04-30T12:04:07.997168Z [init] [kernel/context.cpp:20] [operator()] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
 79 node0 2025-04-30T12:04:08.280800Z [init] [random.cpp:111] [ReportHardwareRand] Using RdSeed as an additional entropy source
 80 node0 2025-04-30T12:04:08.281000Z [init] [random.cpp:114] [ReportHardwareRand] Using RdRand as an additional entropy source
 81 node0 2025-04-30T12:04:08.570032Z [init] [init/common.cpp:119] [StartLogging] Default data directory /home/will/.bitcoin
 82 node0 2025-04-30T12:04:08.571509Z [init] [init/common.cpp:120] [StartLogging] Using data directory /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest
 83 node0 2025-04-30T12:04:08.572671Z [init] [init/common.cpp:129] [StartLogging] Config file: /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/bitcoin.conf
 84 node0 2025-04-30T12:04:08.575630Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: regtest="1"
 85 node0 2025-04-30T12:04:08.577311Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1"
 86 node0 2025-04-30T12:04:08.577440Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] connect="0"
 87 node0 2025-04-30T12:04:08.577565Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] deprecatedrpc="create_bdb"
 88 node0 2025-04-30T12:04:08.577686Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] discover="0"
 89 node0 2025-04-30T12:04:08.577804Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] dnsseed="0"
 90 node0 2025-04-30T12:04:08.578304Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002"
 91 node0 2025-04-30T12:04:08.578434Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0"
 92 node0 2025-04-30T12:04:08.578554Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] keypool="1"
 93 node0 2025-04-30T12:04:08.578672Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] listenonion="0"
 94 node0 2025-04-30T12:04:08.578840Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] maxconnections="94"
 95 node0 2025-04-30T12:04:08.578960Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] natpmp="0"
 96 node0 2025-04-30T12:04:08.579092Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999"
 97 node0 2025-04-30T12:04:08.579213Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] port="11000"
 98 node0 2025-04-30T12:04:08.579333Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0"
 99 node0 2025-04-30T12:04:08.579456Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1"
100 node0 2025-04-30T12:04:08.579577Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcport="16000"
101 node0 2025-04-30T12:04:08.579979Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcservertimeout="99000"
102 node0 2025-04-30T12:04:08.580114Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] server="1"
103 node0 2025-04-30T12:04:08.580237Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0"
104 node0 2025-04-30T12:04:08.580357Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1"
105 node0 2025-04-30T12:04:08.580800Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: datadir="/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0"
106 node0 2025-04-30T12:04:08.581089Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debug=""
107 node0 2025-04-30T12:04:08.581217Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="libevent"
108 node0 2025-04-30T12:04:08.581349Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="leveldb"
109 node0 2025-04-30T12:04:08.581470Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="rand"
110 node0 2025-04-30T12:04:08.581593Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: disablewallet=""
111 node0 2025-04-30T12:04:08.581715Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: loglevel="trace"
112 node0 2025-04-30T12:04:08.581836Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logsourcelocations=""
113 node0 2025-04-30T12:04:08.581955Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logthreadnames=""
114 node0 2025-04-30T12:04:08.582082Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logtimemicros=""
115 node0 2025-04-30T12:04:08.582201Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: maxconnections="32"
116 node0 2025-04-30T12:04:08.582321Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: uacomment="testnode0"
117 node0 2025-04-30T12:04:08.582439Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: v2transport="0"
118 node0 2025-04-30T12:04:08.583953Z [init] [init.cpp:1356] [AppInitMain] Using at most 32 automatic connections (1024 file descriptors available)
119 node0 2025-04-30T12:04:08.607596Z [init] [wallet/init.cpp:120] [Construct] Wallet disabled!
120 node0 2025-04-30T12:04:09.668717Z [init] [httpserver.cpp:239] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128
121 node0 2025-04-30T12:04:09.691201Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address ::1 port 16000
122 node0 2025-04-30T12:04:09.703713Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 16000
123 node0 2025-04-30T12:04:09.704963Z [init] [httpserver.cpp:477] [InitHTTPServer] [http] Initialized HTTP server
124 node0 2025-04-30T12:04:09.706788Z [init] [httpserver.cpp:479] [InitHTTPServer] [http] creating work queue of depth 64
125 node0 2025-04-30T12:04:09.708226Z [init] [rpc/server.cpp:282] [StartRPC] [rpc] Starting RPC
126 node0 2025-04-30T12:04:09.709192Z [init] [httprpc.cpp:364] [StartHTTPRPC] [rpc] Starting HTTP RPC server
127 node0 2025-04-30T12:04:09.714981Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start
128 node0 2025-04-30T12:04:09.718912Z [init] [rpc/request.cpp:138] [GenerateAuthCookie] Generated RPC authentication cookie /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/.cookie
129 node0 2025-04-30T12:04:09.719663Z [init] [rpc/request.cpp:139] [GenerateAuthCookie] Permissions used for cookie: rw-------
130 node0 2025-04-30T12:04:09.720918Z [init] [httprpc.cpp:314] [InitRPCAuthentication] Using random cookie authentication.
131 node0 2025-04-30T12:04:09.724557Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1)
132 node0 2025-04-30T12:04:09.727021Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0)
133 node0 2025-04-30T12:04:09.728798Z [init] [httpserver.cpp:502] [StartHTTPServer] Starting HTTP server with 16 worker threads
134 node0 2025-04-30T12:04:09.963043Z [init] [init.cpp:1477] [AppInitMain] Using /16 prefix for IP bucketing
135 node0 2025-04-30T12:04:09.966726Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading P2P addresses…
136 node0 2025-04-30T12:04:10.005410Z [init] [addrdb.cpp:206] [LoadAddrman] Creating peers.dat because the file was not found ("/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/peers.dat")
137 node0 2025-04-30T12:04:10.021477Z [http] [httpserver.cpp:352] [ThreadHTTP] [http] Entering http event loop
138 node0 2025-04-30T12:04:10.076709Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47108
139 node0 2025-04-30T12:04:10.089528Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading banlist…
140 node0 2025-04-30T12:04:10.090233Z [init] [banman.cpp:42] [LoadBanlist] Recreating the banlist database
141 node0 2025-04-30T12:04:10.098113Z [init] [banman.cpp:68] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  4ms
142 node0 2025-04-30T12:04:10.102616Z [init] [net.cpp:2426] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false
143 node0 2025-04-30T12:04:10.106592Z [init] [net.cpp:3199] [SetNetworkActive] SetNetworkActive: true
144 node0 2025-04-30T12:04:10.117488Z [init] [policy/fees.cpp:563] [CBlockPolicyEstimator] /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/fee_estimates.dat is not found. Continue anyway.
145 node0 2025-04-30T12:04:10.131314Z [init] [init.cpp:1673] [AppInitMain] Cache configuration:
146 node0 2025-04-30T12:04:10.134219Z [init] [init.cpp:1674] [AppInitMain] * Using 2.0 MiB for block index database
147 node0 2025-04-30T12:04:10.135970Z [init] [init.cpp:1682] [AppInitMain] * Using 8.0 MiB for chain state database
148 node0 2025-04-30T12:04:10.143810Z [init] [init.cpp:1245] [InitAndLoadChainstate] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
149 node0 2025-04-30T12:04:10.147153Z [init] [checkqueue.h:147] [CCheckQueue] Script verification uses 15 additional threads
150 node0 2025-04-30T12:04:10.362392Z [init] [node/blockstorage.cpp:1154] [InitBlocksdirXorKey] Using obfuscation key for blocksdir *.dat files (/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/blocks): '391eac751cb1cdce'
151 node0 2025-04-30T12:04:10.369422Z [init] [dbwrapper.cpp:235] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/blocks/index
152 node0 2025-04-30T12:04:10.457976Z [httpworker.12] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__
153 node0 2025-04-30T12:04:10.554284Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully
154 node0 2025-04-30T12:04:10.559470Z [init] [dbwrapper.cpp:268] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/blocks/index: 0000000000000000
155 node0 2025-04-30T12:04:10.576160Z [init] [script/sigcache.cpp:35] [SignatureCache] Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements
156 node0 2025-04-30T12:04:10.587458Z [init] [validation.cpp:2140] [ValidationCache] Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements
157 node0 2025-04-30T12:04:10.589905Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading block index…
158 node0 2025-04-30T12:04:10.590593Z [init] [node/chainstate.cpp:150] [LoadChainstate] Validating signatures for all blocks.
159 node0 2025-04-30T12:04:10.591164Z [init] [node/chainstate.cpp:152] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000
160 node0 2025-04-30T12:04:10.654589Z [init] [node/blockstorage.cpp:508] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0
161 node0 2025-04-30T12:04:10.662815Z [init] [node/blockstorage.cpp:512] [LoadBlockIndexDB] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=200, size=52530, heights=0...199, time=2011-02-02...2011-02-02)
162 node0 2025-04-30T12:04:10.663773Z [init] [node/blockstorage.cpp:523] [LoadBlockIndexDB] Checking all blk files are present...
163 node0 2025-04-30T12:04:10.683403Z [init] [node/chainstate.cpp:87] [CompleteChainstateInitialization] Initializing chainstate Chainstate [ibd] @ height -1 (null)
164 node0 2025-04-30T12:04:10.685514Z [init] [dbwrapper.cpp:235] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/chainstate
165 node0 2025-04-30T12:04:10.722090Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully
166 node0 2025-04-30T12:04:10.724089Z [init] [dbwrapper.cpp:268] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/node0/regtest/chainstate: 7ba26db57efdde8a
167 node0 2025-04-30T12:04:10.738922Z [init] [validation.cpp:4672] [LoadChainTip] Loaded best chain: hashBestChain=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c height=199 date=2011-02-02T23:17:17Z progress=1.000000
168 node0 2025-04-30T12:04:10.744691Z [init] [noui.cpp:57] [noui_InitMessage] init message: Verifying blocks…
169 node0 2025-04-30T12:04:10.748637Z [init] [validation.cpp:4715] [VerifyDB] Verifying last 6 blocks at level 3
170 node0 2025-04-30T12:04:10.749162Z [init] [validation.cpp:4724] [VerifyDB] Verification progress: 0%
171 node0 2025-04-30T12:04:10.756367Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47124
172 node0 2025-04-30T12:04:10.790688Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 16%
173 node0 2025-04-30T12:04:10.794756Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 33%
174 node0 2025-04-30T12:04:10.796837Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 50%
175 node0 2025-04-30T12:04:10.798735Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 66%
176 node0 2025-04-30T12:04:10.800614Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 83%
177 node0 2025-04-30T12:04:10.802140Z [httpworker.6] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__
178 node0 2025-04-30T12:04:10.803224Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 99%
179 node0 2025-04-30T12:04:10.803911Z [init] [validation.cpp:4826] [VerifyDB] Verification: No coin database inconsistencies in last 6 blocks (6 transactions)
180 node0 2025-04-30T12:04:10.806121Z [init] [init.cpp:1330] [InitAndLoadChainstate] Block index and chainstate loaded
181 node0 2025-04-30T12:04:10.812380Z [init] [init.cpp:1779] [AppInitMain] Setting NODE_NETWORK on non-prune mode
182 node0 2025-04-30T12:04:10.832203Z [init] [init.cpp:1889] [AppInitMain] block tree size = 200
183 node0 2025-04-30T12:04:10.832863Z [init] [init.cpp:1902] [AppInitMain] nBestHeight = 199
184 node0 2025-04-30T12:04:10.846326Z [init] [net.cpp:3172] [BindListenPort] Bound to 127.0.0.1:11000
185 node0 2025-04-30T12:04:10.851337Z [init] [noui.cpp:57] [noui_InitMessage] init message: Starting network threads…
186 node0 2025-04-30T12:04:10.866473Z [init] [net.cpp:3362] [Start] DNS seeding disabled
187 node0 2025-04-30T12:04:10.895658Z [init] [noui.cpp:57] [noui_InitMessage] init message: Done loading
188 node0 2025-04-30T12:04:10.900176Z [net] [util/thread.cpp:20] [TraceThread] net thread start
189 node0 2025-04-30T12:04:10.904576Z [initload] [util/thread.cpp:20] [TraceThread] initload thread start
190 node0 2025-04-30T12:04:10.911265Z [initload] [node/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file. Continuing anyway.
191 node0 2025-04-30T12:04:10.912461Z [initload] [util/thread.cpp:22] [TraceThread] initload thread exit
192 node0 2025-04-30T12:04:10.915073Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start
193 node0 2025-04-30T12:04:10.916594Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start
194 node0 2025-04-30T12:04:11.054637Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
195 node0 2025-04-30T12:04:11.055013Z [httpworker.4] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__
196 node0 2025-04-30T12:04:11.067318Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
197 node0 2025-04-30T12:04:11.067668Z [httpworker.11] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__
198 test  2025-04-30T12:04:11.088000Z TestFramework.node0 (DEBUG): RPC successfully started
199 node0 2025-04-30T12:04:11.089320Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
200 node0 2025-04-30T12:04:11.090937Z [httpworker.2] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__
201 test  2025-04-30T12:04:11.114000Z TestFramework (DEBUG): Generate a block with current time
202 test  2025-04-30T12:04:11.114000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
203 node0 2025-04-30T12:04:11.114651Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
204 node0 2025-04-30T12:04:11.115846Z [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__
205 node0 2025-04-30T12:04:11.157065Z [httpworker.13] [node/miner.cpp:168] [CreateNewBlock] CreateNewBlock(): block weight: 904 txs: 0 fees: 0 sigops 400
206 node0 2025-04-30T12:04:11.169212Z [httpworker.13] [validation.cpp:2498] [ConnectBlock] [bench]     - Sanity checks: 0.93ms [0.00s (0.93ms/blk)]
207 node0 2025-04-30T12:04:11.175027Z [httpworker.13] [validation.cpp:2600] [ConnectBlock] [bench]     - Fork checks: 7.59ms [0.01s (7.59ms/blk)]
208 node0 2025-04-30T12:04:11.182180Z [httpworker.13] [validation.cpp:2692] [ConnectBlock] [bench]       - Connect 1 transactions: 5.64ms (5.636ms/tx, 0.000ms/txin) [0.01s (5.64ms/blk)]
209 node0 2025-04-30T12:04:11.185401Z [httpworker.13] [validation.cpp:2714] [ConnectBlock] [bench]     - Verify 0 txins: 9.13ms (0.000ms/txin) [0.01s (9.13ms/blk)]
210 node0 2025-04-30T12:04:11.189313Z [httpworker.13] [node/miner.cpp:183] [CreateNewBlock] [bench] CreateNewBlock() packages: 5.84ms (0 packages, 0 updated descendants), validity: 45.47ms (total 51.31ms)
211 node0 2025-04-30T12:04:11.223490Z [httpworker.13] [validation.cpp:3157] [ConnectTip] [bench]   - Using cached block
212 node0 2025-04-30T12:04:11.224163Z [httpworker.13] [validation.cpp:3166] [ConnectTip] [bench]   - Load block from disk: 0.58ms
213 node0 2025-04-30T12:04:11.224687Z [httpworker.13] [validation.cpp:2498] [ConnectBlock] [bench]     - Sanity checks: 0.01ms [0.00s (0.47ms/blk)]
214 node0 2025-04-30T12:04:11.224958Z [httpworker.13] [validation.cpp:2600] [ConnectBlock] [bench]     - Fork checks: 0.28ms [0.01s (3.93ms/blk)]
215 node0 2025-04-30T12:04:11.225174Z [httpworker.13] [validation.cpp:2692] [ConnectBlock] [bench]       - Connect 1 transactions: 0.19ms (0.191ms/tx, 0.000ms/txin) [0.01s (2.91ms/blk)]
216 node0 2025-04-30T12:04:11.225444Z [httpworker.13] [validation.cpp:2714] [ConnectBlock] [bench]     - Verify 0 txins: 0.46ms (0.000ms/txin) [0.01s (4.80ms/blk)]
217 node0 2025-04-30T12:04:11.230852Z [httpworker.13] [validation.cpp:2730] [ConnectBlock] [bench]     - Write undo data: 4.92ms [0.00s (2.46ms/blk)]
218 node0 2025-04-30T12:04:11.232008Z [httpworker.13] [validation.cpp:2745] [ConnectBlock] [bench]     - Index writing: 1.22ms [0.00s (0.61ms/blk)]
219 node0 2025-04-30T12:04:11.235148Z [httpworker.13] [validationinterface.cpp:249] [BlockChecked] [validation] BlockChecked: block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 state=Valid
220 node0 2025-04-30T12:04:11.237768Z [httpworker.13] [validation.cpp:3183] [ConnectTip] [bench]   - Connect total: 13.37ms [0.01s (6.68ms/blk)]
221 node0 2025-04-30T12:04:11.243752Z [httpworker.13] [validation.cpp:3192] [ConnectTip] [bench]   - Flush: 6.10ms [0.01s (3.05ms/blk)]
222 node0 2025-04-30T12:04:11.244664Z [httpworker.13] [validation.cpp:3202] [ConnectTip] [bench]   - Writing chainstate: 0.93ms [0.00s (0.46ms/blk)]
223 node0 2025-04-30T12:04:11.250592Z [httpworker.13] [validationinterface.cpp:225] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=200 txs removed=0
224 node0 2025-04-30T12:04:11.254057Z [httpworker.13] [validation.cpp:2038] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false)
225 node0 2025-04-30T12:04:11.260853Z [httpworker.13] [validation.cpp:2972] [UpdateTipLog] UpdateTip: new best=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 height=200 version=0x30000000 log2_work=8.651052 tx=201 date='2025-04-30T12:04:11Z' progress=1.000000 cache=0.3MiB(1txo)
226 node0 2025-04-30T12:04:11.262658Z [httpworker.13] [validation.cpp:3218] [ConnectTip] [bench]   - Connect postprocess: 17.90ms [0.02s (8.95ms/blk)]
227 node0 2025-04-30T12:04:11.263369Z [httpworker.13] [validation.cpp:3222] [ConnectTip] [bench] - Connect block: 38.87ms [0.04s (19.44ms/blk)]
228 node0 2025-04-30T12:04:11.267817Z [httpworker.13] [txmempool.cpp:700] [check] [mempool] Checking mempool with 0 transactions and 0 inputs
229 node0 2025-04-30T12:04:11.273883Z [httpworker.13] [validationinterface.cpp:215] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 block height=200
230 node0 2025-04-30T12:04:11.278865Z [httpworker.13] [validationinterface.cpp:179] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 fork block hash=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c (in IBD=false)
231 node0 2025-04-30T12:04:11.282646Z [httpworker.13] [validationinterface.cpp:187] [ActiveTipChange] [validation] ActiveTipChange: new block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 block height=200
232 node0 2025-04-30T12:04:11.293558Z [scheduler] [validationinterface.cpp:225] [operator()] [validation] MempoolTransactionsRemovedForBlock: block height=200 txs removed=0
233 node0 2025-04-30T12:04:11.299180Z [scheduler] [policy/fees.cpp:709] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
234 node0 2025-04-30T12:04:11.301776Z [scheduler] [validationinterface.cpp:215] [operator()] [validation] BlockConnected: block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 block height=200
235 node0 2025-04-30T12:04:11.308353Z [scheduler] [validationinterface.cpp:179] [operator()] [validation] UpdatedBlockTip: new block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 fork block hash=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c (in IBD=false)
236 node0 2025-04-30T12:04:11.311530Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
237 node0 2025-04-30T12:04:11.312059Z [httpworker.7] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__
238 node0 2025-04-30T12:04:11.317733Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
239 node0 2025-04-30T12:04:11.318501Z [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=submitblock user=__cookie__
240 node0 2025-04-30T12:04:11.335680Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
241 node0 2025-04-30T12:04:11.336029Z [httpworker.9] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__
242 node0 2025-04-30T12:04:11.337968Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
243 node0 2025-04-30T12:04:11.338316Z [httpworker.0] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__
244 node0 2025-04-30T12:04:11.340111Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
245 node0 2025-04-30T12:04:11.340445Z [httpworker.10] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__
246 node0 2025-04-30T12:04:11.343720Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:47126
247 node0 2025-04-30T12:04:11.344433Z [httpworker.15] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__
248 test  2025-04-30T12:04:11.349000Z TestFramework (INFO): hook into the net:inbound_message and net:outbound_message tracepoints
249 test  2025-04-30T12:04:12.884000Z TestFramework (INFO): connect a P2P test node to our bitcoind node
250 test  2025-04-30T12:04:12.884000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:11000
251 test  2025-04-30T12:04:12.884000Z TestFramework.p2p (DEBUG): Connected: us=127.0.0.1:47156, them=127.0.0.1:11000
252 test  2025-04-30T12:04:12.884000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11000: msg_version(nVersion=70016 nServices=9 nTime=Wed Apr 30 13:04:12 2025 addrTo=CAddress(nServices=1 net=IPv4 addr=127.0.0.1 port=11000) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0xF0F901511CE84AB8 strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=1)
253 node0 2025-04-30T12:04:12.902348Z [net] [net.cpp:3833] [CNode] [net] Added connection peer=0
254 node0 2025-04-30T12:04:12.906639Z [net] [net.cpp:1854] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:47156 accepted
255 test  2025-04-30T12:04:13.459000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:11000
256 test  2025-04-30T12:04:13.485000Z TestFramework (ERROR): Assertion failed
257                                   Traceback (most recent call last):
258                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/test_framework.py", line 183, in main
259                                       self.run_test()
260                                     File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 259, in run_test
261                                       self.p2p_message_tracepoint_test()
262                                     File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 327, in p2p_message_tracepoint_test
263                                       self.nodes[0].add_p2p_connection(test_node)
264                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/test_node.py", line 736, in add_p2p_connection
265                                       p2p_conn.wait_for_verack()
266                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 692, in wait_for_verack
267                                       self.wait_until(test_function, timeout=timeout)
268                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 601, in wait_until
269                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
270                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/util.py", line 311, in wait_until_helper_internal
271                                       if predicate():
272                                          ^^^^^^^^^^^
273                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 598, in test_function
274                                       assert self.is_connected
275                                              ^^^^^^^^^^^^^^^^^
276                                   AssertionError
277 test  2025-04-30T12:04:13.486000Z TestFramework (DEBUG): Closing down network thread
278 test  2025-04-30T12:04:13.536000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
279 test  2025-04-30T12:04:13.536000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
280 test  2025-04-30T12:04:13.536000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0/test_framework.log
281 test  2025-04-30T12:04:13.536000Z TestFramework (ERROR):
282 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR): Hint: Call /home/will/src/core/bitcoin/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0' to consolidate all logs
283 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR):
284 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
285 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
286 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR):
287
288 node0 stderr ==307456==
289==307456== Process terminating with default action of signal 5 (SIGTRAP)
290==307456==    at 0x590156: ~basic_string (basic_string.h:809)
291==307456==    by 0x590156: (anonymous namespace)::PeerManagerImpl::ProcessMessages(CNode*, std::atomic<bool>&) (net_processing.cpp:5040)
292==307456==    by 0x543DDD: CConnman::ThreadMessageHandler() (net.cpp:3054)
293==307456==    by 0xCBF40E: operator() (std_function.h:591)
294==307456==    by 0xCBF40E: util::TraceThread(std::basic_string_view<char, std::char_traits<char> >, std::function<void ()>) (thread.cpp:21)
295==307456==    by 0x535D56: __invoke_impl<void, void (*)(std::basic_string_view<char>, std::function<void()>), char const*, CConnman::Start(CScheduler&, const Options&)::<lambda()> > (invoke.h:61)
296==307456==    by 0x535D56: __invoke<void (*)(std::basic_string_view<char>, std::function<void()>), char const*, CConnman::Start(CScheduler&, const Options&)::<lambda()> > (invoke.h:96)
297==307456==    by 0x535D56: _M_invoke<0, 1, 2> (std_thread.h:301)
298==307456==    by 0x535D56: operator() (std_thread.h:308)
299==307456==    by 0x535D56: std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(std::basic_string_view<char, std::char_traits<char> >, std::function<void ()>), char const*, CConnman::Start(CScheduler&, CConnman::Options const&)::{lambda()#5}> > >::_M_run() (std_thread.h:253)
300==307456==    by 0x4B70123: execute_native_thread_routine (in /nix/store/7hyxhin05law4mnxsdrmqv30h0rnqdxm-gcc-14.2.0-lib/lib/libstdc++.so.6.0.33)
301==307456==    by 0x4E9DD01: start_thread (in /nix/store/pacbfvpzqz2mksby36awvbcn051zcji3-glibc-2.40-36/lib/libc.so.6)
302==307456==    by 0x4F1D193: clone (in /nix/store/pacbfvpzqz2mksby36awvbcn051zcji3-glibc-2.40-36/lib/libc.so.6)

So it appears most likely to be a use-after-free, double-free or buffer overflow at this tracepoint https://github.com/bitcoin/bitcoin/blob/14b8dfb2bd5e2ca2b7c0c9a7f7d50e1e60adf75c/src/net_processing.cpp#L5040-L5047 as it’s crashing in the destructor…

Will try and investigate a little further

maflcko commented at 12:39 pm on April 30, 2025: member

Yeah, it reminds me of #27380 (comment), which was a similar lifetime issue. ConnectionTypeAsString should be the only call that creates a new string object in this tracepoint here.

I wonder why valgrind only traps and doesn’t print more information about the kind of error.
willcl-ark commented at 12:27 pm on May 1, 2025: member

I was not able to get this to reproduce using any of the sanitizers.

Connecting with gdb, shows all pointers and variables as valid at the callsite. I agree that ConnectionTypeAsString seems the natural culprit as it returns a temporary string, but even patching that to return const *char,still saw SIGTRAP raised.

Stepping through the tracepoint saw it execute without error, so it does seem to be a race/lifetime issue, but not really too sure where else to go from here.
0xB10C commented at 10:53 am on May 2, 2025: contributor

Trying it with pfrom->GetId() as the sole tracepoint (for net::inbound_message, net::outbound_message, and net::inbound_connection) argument produces the same failure. I don’t think it’s related to ConnectionTypeAsString.

It seems to me that all interface_usdt_*.py tests fail under valgrind?
0xB10C commented at 1:10 pm on May 2, 2025: contributor

still saw SIGTRAP raised.

Ah, every time the tracepoint is reached a SIGTRAP is fired. No matter the tracepoint contents, even with an empty one. Valgrind intercepts SIGTRAP and aborts.

==1145996== Process terminating with default action of signal 5 (SIGTRAP)

It might be possible to add a valgrind suppression for this this, but I haven’t tired it yet.
willcl-ark commented at 2:12 pm on May 2, 2025: member

I think it would make most sense here to probably skip these tests when valgrind is enabled.

I reckon that any benefits we’d get by taking the time to fix eBPF/Valgrind incompatibility (if its even fixable) wouldn’t be worth the investment.

They are already being tested via ASan + LSan + UBSan + integer, no depends, USDT, but appear to be being skipped in Msan, depends, even though USDT is enabled. Perhaps we enable that instead to cover memory sanitization?

Contributors
fanquake willcl-ark maflcko 0xB10C