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?
fanquake referenced this in commit 75a185ea3d on May 14, 2025
fanquake commented at 9:59 am on May 14, 2025: member

Opened #32492 to add skipping (for now).
fanquake referenced this in commit c779ee3a40 on May 15, 2025
fanquake commented at 9:20 am on May 15, 2025: member

Closed via #32492.
fanquake closed this on May 15, 2025

Contributors
fanquake willcl-ark maflcko 0xB10C