test: interface_usdt_net.py failure under --valgrind #32374

issue fanquake opened 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

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

/root/ci_scratch/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0'
 test  2025-04-29T11:18:32.583000Z TestFramework (INFO): PRNG seed is: 3961365374660180483 
 test  2025-04-29T11:18:32.583000Z TestFramework (DEBUG): Setting up network thread 
 test  2025-04-29T11:18:32.584000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0 
 test  2025-04-29T11:18:32.584000Z TestFramework (DEBUG): Creating cache directory /root/ci_scratch/build/test/cache/node0 
 test  2025-04-29T11:18:32.585000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 test  2025-04-29T11:18:32.842000Z TestFramework.node0 (DEBUG): RPC successfully started 
 test  2025-04-29T11:18:32.844000Z TestFramework.node0 (DEBUG): RPC successfully started 
 test  2025-04-29T11:18:33.046000Z TestFramework.node0 (DEBUG): Stopping node 
 test  2025-04-29T11:18:33.198000Z TestFramework.node0 (DEBUG): Node stopped 
 test  2025-04-29T11:18:33.200000Z TestFramework (DEBUG): Copy cache directory /root/ci_scratch/build/test/cache/node0 to node 0 
 test  2025-04-29T11:18:33.245000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 node0 2025-04-29T11:18:36.097251Z [init] [init/common.cpp:151] [LogPackageVersion] Bitcoin Core version v29.99.0-c5e44a043563 (release build) 
 node0 2025-04-29T11:18:36.105631Z [init] [init.cpp:722] [InitParameterInteraction] parameter interaction: -bind set -> setting -listen=1 
 node0 2025-04-29T11:18:36.336642Z [init] [kernel/context.cpp:20] [operator()] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 node0 2025-04-29T11:18:36.633915Z [init] [random.cpp:111] [ReportHardwareRand] Using RdSeed as an additional entropy source 
 node0 2025-04-29T11:18:36.634205Z [init] [random.cpp:114] [ReportHardwareRand] Using RdRand as an additional entropy source 
 node0 2025-04-29T11:18:36.957186Z [init] [init/common.cpp:119] [StartLogging] Default data directory /root/.bitcoin 
 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 
 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 
 node0 2025-04-29T11:18:36.963467Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: regtest="1" 
 node0 2025-04-29T11:18:36.965363Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 node0 2025-04-29T11:18:36.965494Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 node0 2025-04-29T11:18:36.965643Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] deprecatedrpc="create_bdb" 
 node0 2025-04-29T11:18:36.965767Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 node0 2025-04-29T11:18:36.965873Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 node0 2025-04-29T11:18:36.966446Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 node0 2025-04-29T11:18:36.966569Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 node0 2025-04-29T11:18:36.966697Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 node0 2025-04-29T11:18:36.966802Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 node0 2025-04-29T11:18:36.967011Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] maxconnections="94" 
 node0 2025-04-29T11:18:36.967152Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 node0 2025-04-29T11:18:36.967262Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999" 
 node0 2025-04-29T11:18:36.967370Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] port="11000" 
 node0 2025-04-29T11:18:36.967478Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 node0 2025-04-29T11:18:36.967588Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1" 
 node0 2025-04-29T11:18:36.967721Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcport="16000" 
 node0 2025-04-29T11:18:36.968178Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcservertimeout="99000" 
 node0 2025-04-29T11:18:36.968304Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] server="1" 
 node0 2025-04-29T11:18:36.968412Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 node0 2025-04-29T11:18:36.968518Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 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" 
 node0 2025-04-29T11:18:36.969364Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debug="" 
 node0 2025-04-29T11:18:36.969489Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 node0 2025-04-29T11:18:36.969597Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 node0 2025-04-29T11:18:36.969725Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="rand" 
 node0 2025-04-29T11:18:36.969840Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: disablewallet="" 
 node0 2025-04-29T11:18:36.969960Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: loglevel="trace" 
 node0 2025-04-29T11:18:36.970069Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 node0 2025-04-29T11:18:36.970190Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logthreadnames="" 
 node0 2025-04-29T11:18:36.970293Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logtimemicros="" 
 node0 2025-04-29T11:18:36.970398Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: maxconnections="32" 
 node0 2025-04-29T11:18:36.970504Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 node0 2025-04-29T11:18:36.970605Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: v2transport="0" 
 node0 2025-04-29T11:18:36.972402Z [init] [init.cpp:1356] [AppInitMain] Using at most 32 automatic connections (1024 file descriptors available) 
 node0 2025-04-29T11:18:36.999851Z [init] [wallet/init.cpp:120] [Construct] Wallet disabled! 
 node0 2025-04-29T11:18:38.109153Z [init] [httpserver.cpp:239] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 node0 2025-04-29T11:18:38.128450Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address ::1 port 16000 
 node0 2025-04-29T11:18:38.144722Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 16000 
 node0 2025-04-29T11:18:38.146313Z [init] [httpserver.cpp:477] [InitHTTPServer] [http] Initialized HTTP server 
 node0 2025-04-29T11:18:38.148475Z [init] [httpserver.cpp:479] [InitHTTPServer] [http] creating work queue of depth 64 
 node0 2025-04-29T11:18:38.150171Z [init] [rpc/server.cpp:282] [StartRPC] [rpc] Starting RPC 
 node0 2025-04-29T11:18:38.151231Z [init] [httprpc.cpp:364] [StartHTTPRPC] [rpc] Starting HTTP RPC server 
 node0 2025-04-29T11:18:38.168763Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start 
 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 
 node0 2025-04-29T11:18:38.178436Z [init] [rpc/request.cpp:139] [GenerateAuthCookie] Permissions used for cookie: rw------- 
 node0 2025-04-29T11:18:38.179783Z [init] [httprpc.cpp:314] [InitRPCAuthentication] Using random cookie authentication. 
 node0 2025-04-29T11:18:38.183825Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1) 
 node0 2025-04-29T11:18:38.186296Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0) 
 node0 2025-04-29T11:18:38.188282Z [init] [httpserver.cpp:502] [StartHTTPServer] Starting HTTP server with 16 worker threads 
 node0 2025-04-29T11:18:38.456022Z [init] [init.cpp:1477] [AppInitMain] Using /16 prefix for IP bucketing 
 node0 2025-04-29T11:18:38.459956Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading P2P addresses… 
 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") 
 node0 2025-04-29T11:18:38.526349Z [http] [httpserver.cpp:352] [ThreadHTTP] [http] Entering http event loop 
 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 
 node0 2025-04-29T11:18:38.676905Z [httpworker.8] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2025-04-29T11:18:38.715210Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading banlist… 
 node0 2025-04-29T11:18:38.716049Z [init] [banman.cpp:42] [LoadBanlist] Recreating the banlist database 
 node0 2025-04-29T11:18:38.783159Z [init] [banman.cpp:68] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  60ms 
 node0 2025-04-29T11:18:38.794771Z [init] [net.cpp:2426] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false 
 node0 2025-04-29T11:18:38.804540Z [init] [net.cpp:3199] [SetNetworkActive] SetNetworkActive: true 
 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. 
 node0 2025-04-29T11:18:38.835593Z [init] [init.cpp:1673] [AppInitMain] Cache configuration: 
 node0 2025-04-29T11:18:38.839026Z [init] [init.cpp:1674] [AppInitMain] * Using 2.0 MiB for block index database 
 node0 2025-04-29T11:18:38.841049Z [init] [init.cpp:1682] [AppInitMain] * Using 8.0 MiB for chain state database 
 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) 
 node0 2025-04-29T11:18:38.854553Z [init] [checkqueue.h:147] [CCheckQueue] Script verification uses 15 additional threads 
 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' 
 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 
 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 
 node0 2025-04-29T11:18:39.256674Z [httpworker.12] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2025-04-29T11:18:39.269032Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully 
 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 
 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 
 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 
 node0 2025-04-29T11:18:39.319018Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading block index… 
 node0 2025-04-29T11:18:39.319818Z [init] [node/chainstate.cpp:150] [LoadChainstate] Validating signatures for all blocks. 
 node0 2025-04-29T11:18:39.320483Z [init] [node/chainstate.cpp:152] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 node0 2025-04-29T11:18:39.387297Z [init] [node/blockstorage.cpp:508] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
 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) 
 node0 2025-04-29T11:18:39.397605Z [init] [node/blockstorage.cpp:523] [LoadBlockIndexDB] Checking all blk files are present... 
 node0 2025-04-29T11:18:39.418276Z [init] [node/chainstate.cpp:87] [CompleteChainstateInitialization] Initializing chainstate Chainstate [ibd] @ height -1 (null) 
 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 
 node0 2025-04-29T11:18:39.432880Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully 
 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 
 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 
 node0 2025-04-29T11:18:39.458142Z [init] [noui.cpp:57] [noui_InitMessage] init message: Verifying blocks… 
 node0 2025-04-29T11:18:39.462490Z [init] [validation.cpp:4762] [VerifyDB] Verifying last 6 blocks at level 3 
 node0 2025-04-29T11:18:39.463138Z [init] [validation.cpp:4771] [VerifyDB] Verification progress: 0% 
 node0 2025-04-29T11:18:39.502551Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 16% 
 node0 2025-04-29T11:18:39.507494Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 33% 
 node0 2025-04-29T11:18:39.511317Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 50% 
 node0 2025-04-29T11:18:39.513636Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 66% 
 node0 2025-04-29T11:18:39.516569Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 83% 
 node0 2025-04-29T11:18:39.519193Z [init] [validation.cpp:4779] [VerifyDB] Verification progress: 99% 
 node0 2025-04-29T11:18:39.519738Z [init] [validation.cpp:4873] [VerifyDB] Verification: No coin database inconsistencies in last 6 blocks (6 transactions) 
 node0 2025-04-29T11:18:39.522169Z [init] [init.cpp:1330] [InitAndLoadChainstate] Block index and chainstate loaded 
 node0 2025-04-29T11:18:39.529187Z [init] [init.cpp:1779] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
 node0 2025-04-29T11:18:39.558905Z [init] [init.cpp:1889] [AppInitMain] block tree size = 200 
 node0 2025-04-29T11:18:39.560014Z [init] [init.cpp:1902] [AppInitMain] nBestHeight = 199 
 node0 2025-04-29T11:18:39.582910Z [init] [net.cpp:3172] [BindListenPort] Bound to 127.0.0.1:11000 
 node0 2025-04-29T11:18:39.590514Z [init] [noui.cpp:57] [noui_InitMessage] init message: Starting network threads… 
 node0 2025-04-29T11:18:39.621345Z [init] [net.cpp:3362] [Start] DNS seeding disabled 
 node0 2025-04-29T11:18:39.665227Z [init] [noui.cpp:57] [noui_InitMessage] init message: Done loading 
 node0 2025-04-29T11:18:39.670899Z [initload] [util/thread.cpp:20] [TraceThread] initload thread start 
 node0 2025-04-29T11:18:39.693254Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
 node0 2025-04-29T11:18:39.699831Z [initload] [node/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file. Continuing anyway. 
 node0 2025-04-29T11:18:39.700887Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
 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 
 node0 2025-04-29T11:18:39.715532Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
 node0 2025-04-29T11:18:39.718248Z [initload] [util/thread.cpp:22] [TraceThread] initload thread exit 
 node0 2025-04-29T11:18:39.727452Z [httpworker.5] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 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 
 node0 2025-04-29T11:18:39.762383Z [httpworker.0] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 test  2025-04-29T11:18:39.824000Z TestFramework.node0 (DEBUG): RPC successfully started 
 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 
 node0 2025-04-29T11:18:39.830188Z [httpworker.14] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
 test  2025-04-29T11:18:39.879000Z TestFramework (DEBUG): Generate a block with current time 
 test  2025-04-29T11:18:39.879000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress` 
 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 
 node0 2025-04-29T11:18:39.884083Z [httpworker.3] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__ 
 node0 2025-04-29T11:18:39.956014Z [httpworker.3] [node/miner.cpp:168] [CreateNewBlock] CreateNewBlock(): block weight: 904 txs: 0 fees: 0 sigops 400 
 node0 2025-04-29T11:18:39.969090Z [httpworker.3] [validation.cpp:2524] [ConnectBlock] [bench]     - Sanity checks: 0.88ms [0.00s (0.88ms/blk)] 
 node0 2025-04-29T11:18:39.975541Z [httpworker.3] [validation.cpp:2626] [ConnectBlock] [bench]     - Fork checks: 8.22ms [0.01s (8.22ms/blk)] 
 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)] 
 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)] 
 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) 
 node0 2025-04-29T11:18:39.999455Z [httpworker.3] [validation.cpp:4421] [AcceptBlockHeader] [validation] Saw new header hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf height=200 
 node0 2025-04-29T11:18:40.029510Z [httpworker.3] [validation.cpp:3187] [ConnectTip] [bench]   - Using cached block 
 node0 2025-04-29T11:18:40.030315Z [httpworker.3] [validation.cpp:3196] [ConnectTip] [bench]   - Load block from disk: 0.69ms 
 node0 2025-04-29T11:18:40.031000Z [httpworker.3] [validation.cpp:2524] [ConnectBlock] [bench]     - Sanity checks: 0.01ms [0.00s (0.44ms/blk)] 
 node0 2025-04-29T11:18:40.031290Z [httpworker.3] [validation.cpp:2626] [ConnectBlock] [bench]     - Fork checks: 0.31ms [0.01s (4.26ms/blk)] 
 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)] 
 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)] 
 node0 2025-04-29T11:18:40.038082Z [httpworker.3] [validation.cpp:2756] [ConnectBlock] [bench]     - Write undo data: 5.80ms [0.01s (2.90ms/blk)] 
 node0 2025-04-29T11:18:40.039358Z [httpworker.3] [validation.cpp:2771] [ConnectBlock] [bench]     - Index writing: 1.39ms [0.00s (0.70ms/blk)] 
 node0 2025-04-29T11:18:40.042890Z [httpworker.3] [validationinterface.cpp:249] [BlockChecked] [validation] BlockChecked: block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf state=Valid 
 node0 2025-04-29T11:18:40.045771Z [httpworker.3] [validation.cpp:3213] [ConnectTip] [bench]   - Connect total: 15.21ms [0.02s (7.60ms/blk)] 
 node0 2025-04-29T11:18:40.052408Z [httpworker.3] [validation.cpp:3222] [ConnectTip] [bench]   - Flush: 6.76ms [0.01s (3.38ms/blk)] 
 node0 2025-04-29T11:18:40.053493Z [httpworker.3] [validation.cpp:3232] [ConnectTip] [bench]   - Writing chainstate: 1.08ms [0.00s (0.54ms/blk)] 
 node0 2025-04-29T11:18:40.060179Z [httpworker.3] [validationinterface.cpp:225] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=200 txs removed=0 
 node0 2025-04-29T11:18:40.063752Z [httpworker.3] [validation.cpp:2038] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false) 
 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) 
 node0 2025-04-29T11:18:40.071460Z [httpworker.3] [validation.cpp:3248] [ConnectTip] [bench]   - Connect postprocess: 17.94ms [0.02s (8.97ms/blk)] 
 node0 2025-04-29T11:18:40.072213Z [httpworker.3] [validation.cpp:3252] [ConnectTip] [bench] - Connect block: 41.68ms [0.04s (20.84ms/blk)] 
 node0 2025-04-29T11:18:40.076785Z [httpworker.3] [txmempool.cpp:700] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
 node0 2025-04-29T11:18:40.083095Z [httpworker.3] [validationinterface.cpp:215] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf block height=200 
 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) 
 node0 2025-04-29T11:18:40.092373Z [httpworker.3] [validationinterface.cpp:187] [ActiveTipChange] [validation] ActiveTipChange: new block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf block height=200 
 node0 2025-04-29T11:18:40.110192Z [scheduler] [validationinterface.cpp:225] [operator()] [validation] MempoolTransactionsRemovedForBlock: block height=200 txs removed=0 
 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 
 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 
 node0 2025-04-29T11:18:40.137281Z [httpworker.8] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 node0 2025-04-29T11:18:40.153720Z [scheduler] [validationinterface.cpp:215] [operator()] [validation] BlockConnected: block hash=7e51c7ac54d64fd0027d79883558f242c696b001fd60e4a9c464136e862707cf block height=200 
 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) 
 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 
 node0 2025-04-29T11:18:40.186776Z [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=submitblock user=__cookie__ 
 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 
 node0 2025-04-29T11:18:40.233363Z [httpworker.2] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ 
 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 
 node0 2025-04-29T11:18:40.240195Z [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 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 
 node0 2025-04-29T11:18:40.244314Z [httpworker.4] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__ 
 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 
 node0 2025-04-29T11:18:40.254891Z [httpworker.10] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 test  2025-04-29T11:18:40.263000Z TestFramework (INFO): hook into the net:inbound_message and net:outbound_message tracepoints 
 test  2025-04-29T11:18:41.320000Z TestFramework (INFO): connect a P2P test node to our bitcoind node 
 test  2025-04-29T11:18:41.321000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:11000 
 test  2025-04-29T11:18:41.321000Z TestFramework.p2p (DEBUG): Connected: us=127.0.0.1:41596, them=127.0.0.1:11000 
 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) 
 node0 2025-04-29T11:18:41.371553Z [net] [net.cpp:3833] [CNode] [net] Added connection peer=0 
 node0 2025-04-29T11:18:41.377182Z [net] [net.cpp:1854] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:41596 accepted 
 test  2025-04-29T11:18:42.141000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:11000 
 test  2025-04-29T11:18:42.173000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/root/ci_scratch/test/functional/test_framework/test_framework.py", line 183, in main
                                       self.run_test()
                                     File "/root/ci_scratch/build/test/functional/interface_usdt_net.py", line 259, in run_test
                                       self.p2p_message_tracepoint_test()
                                     File "/root/ci_scratch/build/test/functional/interface_usdt_net.py", line 327, in p2p_message_tracepoint_test
                                       self.nodes[0].add_p2p_connection(test_node)
                                     File "/root/ci_scratch/test/functional/test_framework/test_node.py", line 736, in add_p2p_connection
                                       p2p_conn.wait_for_verack()
                                     File "/root/ci_scratch/test/functional/test_framework/p2p.py", line 692, in wait_for_verack
                                       self.wait_until(test_function, timeout=timeout)
                                     File "/root/ci_scratch/test/functional/test_framework/p2p.py", line 601, in wait_until
                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
                                     File "/root/ci_scratch/test/functional/test_framework/util.py", line 311, in wait_until_helper_internal
                                       if predicate():
                                          ^^^^^^^^^^^
                                     File "/root/ci_scratch/test/functional/test_framework/p2p.py", line 598, in test_function
                                       assert self.is_connected
                                              ^^^^^^^^^^^^^^^^^
                                   AssertionError
 test  2025-04-29T11:18:42.176000Z TestFramework (DEBUG): Closing down network thread 
 test  2025-04-29T11:18:42.227000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later. 
 test  2025-04-29T11:18:42.227000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250429_111832/interface_usdt_net_0 
 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 
 test  2025-04-29T11:18:42.227000Z TestFramework (ERROR): 
 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 
 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): 
 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. 
 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues 
 test  2025-04-29T11:18:42.228000Z TestFramework (ERROR): 

 node0 stderr ==1145996== 
==1145996== Process terminating with default action of signal 5 (SIGTRAP)
==1145996==    at 0x41EF0E6: ~basic_string (basic_string.h:809)
==1145996==    by 0x41EF0E6: (anonymous namespace)::PeerManagerImpl::ProcessMessages(CNode*, std::atomic<bool>&) (net_processing.cpp:5006)
==1145996==    by 0x41A782D: CConnman::ThreadMessageHandler() (net.cpp:3054)
==1145996==    by 0x4877F0E: operator() (std_function.h:591)
==1145996==    by 0x4877F0E: util::TraceThread(std::basic_string_view<char, std::char_traits<char> >, std::function<void ()>) (thread.cpp:21)
==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)
==1145996==    by 0x4199DC6: __invoke<void (*)(std::basic_string_view<char>, std::function<void()>), char const*, CConnman::Start(CScheduler&, const Options&)::<lambda()> > (invoke.h:96)
==1145996==    by 0x4199DC6: _M_invoke<0, 1, 2> (std_thread.h:301)
==1145996==    by 0x4199DC6: operator() (std_thread.h:308)
==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)
==1145996==    by 0x576CDB3: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.33)
==1145996==    by 0x5AB1AA3: start_thread (pthread_create.c:447)
==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

<details> <summary>Details</summary>

bitcoin on  master [$?⇡] via △ v3.30.5 via 🐍 v3.12.7 via ❄️  impure (nix-shell-env)
❯ just build -DWITH_USDT=ON
configure running
configure complete
build running
build complete

bitcoin on  master [$?⇡] via △ v3.30.5 via 🐍 v3.12.7 via ❄️  impure (nix-shell-env) took 41s
❯ 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
Temporary test directory at /tmp/test_runner_₿_🏃_20250430_130404
Remaining jobs: [interface_usdt_net.py]
1/1 - interface_usdt_net.py failed, Duration: 9 s

stdout:
2025-04-30T12:04:04.799000Z TestFramework (INFO): PRNG seed is: 4383659148042625286
2025-04-30T12:04:04.799000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
2025-04-30T12:04:11.349000Z TestFramework (INFO): hook into the net:inbound_message and net:outbound_message tracepoints
2025-04-30T12:04:12.884000Z TestFramework (INFO): connect a P2P test node to our bitcoind node
2025-04-30T12:04:13.485000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/will/src/core/bitcoin/test/functional/test_framework/test_framework.py", line 183, in main
    self.run_test()
  File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 259, in run_test
    self.p2p_message_tracepoint_test()
  File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 327, in p2p_message_tracepoint_test
    self.nodes[0].add_p2p_connection(test_node)
  File "/home/will/src/core/bitcoin/test/functional/test_framework/test_node.py", line 736, in add_p2p_connection
    p2p_conn.wait_for_verack()
  File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 692, in wait_for_verack
    self.wait_until(test_function, timeout=timeout)
  File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 601, in wait_until
    wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
  File "/home/will/src/core/bitcoin/test/functional/test_framework/util.py", line 311, in wait_until_helper_internal
    if predicate():
       ^^^^^^^^^^^
  File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 598, in test_function
    assert self.is_connected
           ^^^^^^^^^^^^^^^^^
AssertionError
2025-04-30T12:04:13.536000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-04-30T12:04:13.536000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
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
2025-04-30T12:04:13.536000Z TestFramework (ERROR):
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
2025-04-30T12:04:13.537000Z TestFramework (ERROR):
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.
2025-04-30T12:04:13.537000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-04-30T12:04:13.537000Z TestFramework (ERROR):


stderr:
[node 0] Cleaning up leftover process



TEST                  | STATUS    | DURATION

interface_usdt_net.py | ✖ Failed  | 9 s

ALL                   | ✖ Failed  | 9 s (accumulated)
Runtime: 9 s


bitcoin on  master [$?⇡] via △ v3.30.5 via 🐍 v3.12.7 via ❄️  impure (nix-shell-env) took 9s
❯ sudo /home/will/src/core/bitcoin/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0'
 test  2025-04-30T12:04:04.799000Z TestFramework (INFO): PRNG seed is: 4383659148042625286
 test  2025-04-30T12:04:04.799000Z TestFramework (DEBUG): Setting up network thread
 test  2025-04-30T12:04:04.799000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
 test  2025-04-30T12:04:04.799000Z TestFramework (DEBUG): Creating cache directory /home/will/src/core/bitcoin/build/test/cache/node0
 test  2025-04-30T12:04:04.800000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
 test  2025-04-30T12:04:05.052000Z TestFramework.node0 (DEBUG): RPC successfully started
 test  2025-04-30T12:04:05.053000Z TestFramework.node0 (DEBUG): RPC successfully started
 test  2025-04-30T12:04:05.116000Z TestFramework.node0 (DEBUG): Stopping node
 test  2025-04-30T12:04:05.267000Z TestFramework.node0 (DEBUG): Node stopped
 test  2025-04-30T12:04:05.267000Z TestFramework (DEBUG): Copy cache directory /home/will/src/core/bitcoin/build/test/cache/node0 to node 0
 test  2025-04-30T12:04:05.277000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
 node0 2025-04-30T12:04:07.780089Z [init] [init/common.cpp:151] [LogPackageVersion] Bitcoin Core version v29.99.0-14b8dfb2bd5e (release build)
 node0 2025-04-30T12:04:07.788485Z [init] [init.cpp:722] [InitParameterInteraction] parameter interaction: -bind set -> setting -listen=1
 node0 2025-04-30T12:04:07.997168Z [init] [kernel/context.cpp:20] [operator()] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
 node0 2025-04-30T12:04:08.280800Z [init] [random.cpp:111] [ReportHardwareRand] Using RdSeed as an additional entropy source
 node0 2025-04-30T12:04:08.281000Z [init] [random.cpp:114] [ReportHardwareRand] Using RdRand as an additional entropy source
 node0 2025-04-30T12:04:08.570032Z [init] [init/common.cpp:119] [StartLogging] Default data directory /home/will/.bitcoin
 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
 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
 node0 2025-04-30T12:04:08.575630Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: regtest="1"
 node0 2025-04-30T12:04:08.577311Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1"
 node0 2025-04-30T12:04:08.577440Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] connect="0"
 node0 2025-04-30T12:04:08.577565Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] deprecatedrpc="create_bdb"
 node0 2025-04-30T12:04:08.577686Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] discover="0"
 node0 2025-04-30T12:04:08.577804Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] dnsseed="0"
 node0 2025-04-30T12:04:08.578304Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002"
 node0 2025-04-30T12:04:08.578434Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0"
 node0 2025-04-30T12:04:08.578554Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] keypool="1"
 node0 2025-04-30T12:04:08.578672Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] listenonion="0"
 node0 2025-04-30T12:04:08.578840Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] maxconnections="94"
 node0 2025-04-30T12:04:08.578960Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] natpmp="0"
 node0 2025-04-30T12:04:08.579092Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] peertimeout="999999999"
 node0 2025-04-30T12:04:08.579213Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] port="11000"
 node0 2025-04-30T12:04:08.579333Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0"
 node0 2025-04-30T12:04:08.579456Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcdoccheck="1"
 node0 2025-04-30T12:04:08.579577Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcport="16000"
 node0 2025-04-30T12:04:08.579979Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] rpcservertimeout="99000"
 node0 2025-04-30T12:04:08.580114Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] server="1"
 node0 2025-04-30T12:04:08.580237Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0"
 node0 2025-04-30T12:04:08.580357Z [init] [common/args.cpp:850] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1"
 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"
 node0 2025-04-30T12:04:08.581089Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debug=""
 node0 2025-04-30T12:04:08.581217Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="libevent"
 node0 2025-04-30T12:04:08.581349Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="leveldb"
 node0 2025-04-30T12:04:08.581470Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: debugexclude="rand"
 node0 2025-04-30T12:04:08.581593Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: disablewallet=""
 node0 2025-04-30T12:04:08.581715Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: loglevel="trace"
 node0 2025-04-30T12:04:08.581836Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logsourcelocations=""
 node0 2025-04-30T12:04:08.581955Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logthreadnames=""
 node0 2025-04-30T12:04:08.582082Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: logtimemicros=""
 node0 2025-04-30T12:04:08.582201Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: maxconnections="32"
 node0 2025-04-30T12:04:08.582321Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: uacomment="testnode0"
 node0 2025-04-30T12:04:08.582439Z [init] [common/args.cpp:850] [logArgsPrefix] Command-line arg: v2transport="0"
 node0 2025-04-30T12:04:08.583953Z [init] [init.cpp:1356] [AppInitMain] Using at most 32 automatic connections (1024 file descriptors available)
 node0 2025-04-30T12:04:08.607596Z [init] [wallet/init.cpp:120] [Construct] Wallet disabled!
 node0 2025-04-30T12:04:09.668717Z [init] [httpserver.cpp:239] [InitHTTPAllowList] [http] Allowing HTTP connections from: 127.0.0.0/8 ::1/128
 node0 2025-04-30T12:04:09.691201Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address ::1 port 16000
 node0 2025-04-30T12:04:09.703713Z [init] [httpserver.cpp:392] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 16000
 node0 2025-04-30T12:04:09.704963Z [init] [httpserver.cpp:477] [InitHTTPServer] [http] Initialized HTTP server
 node0 2025-04-30T12:04:09.706788Z [init] [httpserver.cpp:479] [InitHTTPServer] [http] creating work queue of depth 64
 node0 2025-04-30T12:04:09.708226Z [init] [rpc/server.cpp:282] [StartRPC] [rpc] Starting RPC
 node0 2025-04-30T12:04:09.709192Z [init] [httprpc.cpp:364] [StartHTTPRPC] [rpc] Starting HTTP RPC server
 node0 2025-04-30T12:04:09.714981Z [scheduler] [util/thread.cpp:20] [TraceThread] scheduler thread start
 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
 node0 2025-04-30T12:04:09.719663Z [init] [rpc/request.cpp:139] [GenerateAuthCookie] Permissions used for cookie: rw-------
 node0 2025-04-30T12:04:09.720918Z [init] [httprpc.cpp:314] [InitRPCAuthentication] Using random cookie authentication.
 node0 2025-04-30T12:04:09.724557Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for / (exactmatch 1)
 node0 2025-04-30T12:04:09.727021Z [init] [httpserver.cpp:759] [RegisterHTTPHandler] [http] Registering HTTP handler for /wallet/ (exactmatch 0)
 node0 2025-04-30T12:04:09.728798Z [init] [httpserver.cpp:502] [StartHTTPServer] Starting HTTP server with 16 worker threads
 node0 2025-04-30T12:04:09.963043Z [init] [init.cpp:1477] [AppInitMain] Using /16 prefix for IP bucketing
 node0 2025-04-30T12:04:09.966726Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading P2P addresses…
 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")
 node0 2025-04-30T12:04:10.021477Z [http] [httpserver.cpp:352] [ThreadHTTP] [http] Entering http event loop
 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
 node0 2025-04-30T12:04:10.089528Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading banlist…
 node0 2025-04-30T12:04:10.090233Z [init] [banman.cpp:42] [LoadBanlist] Recreating the banlist database
 node0 2025-04-30T12:04:10.098113Z [init] [banman.cpp:68] [DumpBanlist] [net] Flushed 0 banned node addresses/subnets to disk  4ms
 node0 2025-04-30T12:04:10.102616Z [init] [net.cpp:2426] [SetTryNewOutboundPeer] [net] setting try another outbound peer=false
 node0 2025-04-30T12:04:10.106592Z [init] [net.cpp:3199] [SetNetworkActive] SetNetworkActive: true
 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.
 node0 2025-04-30T12:04:10.131314Z [init] [init.cpp:1673] [AppInitMain] Cache configuration:
 node0 2025-04-30T12:04:10.134219Z [init] [init.cpp:1674] [AppInitMain] * Using 2.0 MiB for block index database
 node0 2025-04-30T12:04:10.135970Z [init] [init.cpp:1682] [AppInitMain] * Using 8.0 MiB for chain state database
 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)
 node0 2025-04-30T12:04:10.147153Z [init] [checkqueue.h:147] [CCheckQueue] Script verification uses 15 additional threads
 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'
 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
 node0 2025-04-30T12:04:10.457976Z [httpworker.12] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__
 node0 2025-04-30T12:04:10.554284Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully
 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
 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
 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
 node0 2025-04-30T12:04:10.589905Z [init] [noui.cpp:57] [noui_InitMessage] init message: Loading block index…
 node0 2025-04-30T12:04:10.590593Z [init] [node/chainstate.cpp:150] [LoadChainstate] Validating signatures for all blocks.
 node0 2025-04-30T12:04:10.591164Z [init] [node/chainstate.cpp:152] [LoadChainstate] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000
 node0 2025-04-30T12:04:10.654589Z [init] [node/blockstorage.cpp:508] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0
 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)
 node0 2025-04-30T12:04:10.663773Z [init] [node/blockstorage.cpp:523] [LoadBlockIndexDB] Checking all blk files are present...
 node0 2025-04-30T12:04:10.683403Z [init] [node/chainstate.cpp:87] [CompleteChainstateInitialization] Initializing chainstate Chainstate [ibd] @ height -1 (null)
 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
 node0 2025-04-30T12:04:10.722090Z [init] [dbwrapper.cpp:243] [CDBWrapper] Opened LevelDB successfully
 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
 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
 node0 2025-04-30T12:04:10.744691Z [init] [noui.cpp:57] [noui_InitMessage] init message: Verifying blocks…
 node0 2025-04-30T12:04:10.748637Z [init] [validation.cpp:4715] [VerifyDB] Verifying last 6 blocks at level 3
 node0 2025-04-30T12:04:10.749162Z [init] [validation.cpp:4724] [VerifyDB] Verification progress: 0%
 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
 node0 2025-04-30T12:04:10.790688Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 16%
 node0 2025-04-30T12:04:10.794756Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 33%
 node0 2025-04-30T12:04:10.796837Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 50%
 node0 2025-04-30T12:04:10.798735Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 66%
 node0 2025-04-30T12:04:10.800614Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 83%
 node0 2025-04-30T12:04:10.802140Z [httpworker.6] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__
 node0 2025-04-30T12:04:10.803224Z [init] [validation.cpp:4732] [VerifyDB] Verification progress: 99%
 node0 2025-04-30T12:04:10.803911Z [init] [validation.cpp:4826] [VerifyDB] Verification: No coin database inconsistencies in last 6 blocks (6 transactions)
 node0 2025-04-30T12:04:10.806121Z [init] [init.cpp:1330] [InitAndLoadChainstate] Block index and chainstate loaded
 node0 2025-04-30T12:04:10.812380Z [init] [init.cpp:1779] [AppInitMain] Setting NODE_NETWORK on non-prune mode
 node0 2025-04-30T12:04:10.832203Z [init] [init.cpp:1889] [AppInitMain] block tree size = 200
 node0 2025-04-30T12:04:10.832863Z [init] [init.cpp:1902] [AppInitMain] nBestHeight = 199
 node0 2025-04-30T12:04:10.846326Z [init] [net.cpp:3172] [BindListenPort] Bound to 127.0.0.1:11000
 node0 2025-04-30T12:04:10.851337Z [init] [noui.cpp:57] [noui_InitMessage] init message: Starting network threads…
 node0 2025-04-30T12:04:10.866473Z [init] [net.cpp:3362] [Start] DNS seeding disabled
 node0 2025-04-30T12:04:10.895658Z [init] [noui.cpp:57] [noui_InitMessage] init message: Done loading
 node0 2025-04-30T12:04:10.900176Z [net] [util/thread.cpp:20] [TraceThread] net thread start
 node0 2025-04-30T12:04:10.904576Z [initload] [util/thread.cpp:20] [TraceThread] initload thread start
 node0 2025-04-30T12:04:10.911265Z [initload] [node/mempool_persist.cpp:47] [LoadMempool] Failed to open mempool file. Continuing anyway.
 node0 2025-04-30T12:04:10.912461Z [initload] [util/thread.cpp:22] [TraceThread] initload thread exit
 node0 2025-04-30T12:04:10.915073Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start
 node0 2025-04-30T12:04:10.916594Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start
 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
 node0 2025-04-30T12:04:11.055013Z [httpworker.4] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__
 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
 node0 2025-04-30T12:04:11.067668Z [httpworker.11] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__
 test  2025-04-30T12:04:11.088000Z TestFramework.node0 (DEBUG): RPC successfully started
 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
 node0 2025-04-30T12:04:11.090937Z [httpworker.2] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__
 test  2025-04-30T12:04:11.114000Z TestFramework (DEBUG): Generate a block with current time
 test  2025-04-30T12:04:11.114000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
 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
 node0 2025-04-30T12:04:11.115846Z [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__
 node0 2025-04-30T12:04:11.157065Z [httpworker.13] [node/miner.cpp:168] [CreateNewBlock] CreateNewBlock(): block weight: 904 txs: 0 fees: 0 sigops 400
 node0 2025-04-30T12:04:11.169212Z [httpworker.13] [validation.cpp:2498] [ConnectBlock] [bench]     - Sanity checks: 0.93ms [0.00s (0.93ms/blk)]
 node0 2025-04-30T12:04:11.175027Z [httpworker.13] [validation.cpp:2600] [ConnectBlock] [bench]     - Fork checks: 7.59ms [0.01s (7.59ms/blk)]
 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)]
 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)]
 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)
 node0 2025-04-30T12:04:11.223490Z [httpworker.13] [validation.cpp:3157] [ConnectTip] [bench]   - Using cached block
 node0 2025-04-30T12:04:11.224163Z [httpworker.13] [validation.cpp:3166] [ConnectTip] [bench]   - Load block from disk: 0.58ms
 node0 2025-04-30T12:04:11.224687Z [httpworker.13] [validation.cpp:2498] [ConnectBlock] [bench]     - Sanity checks: 0.01ms [0.00s (0.47ms/blk)]
 node0 2025-04-30T12:04:11.224958Z [httpworker.13] [validation.cpp:2600] [ConnectBlock] [bench]     - Fork checks: 0.28ms [0.01s (3.93ms/blk)]
 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)]
 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)]
 node0 2025-04-30T12:04:11.230852Z [httpworker.13] [validation.cpp:2730] [ConnectBlock] [bench]     - Write undo data: 4.92ms [0.00s (2.46ms/blk)]
 node0 2025-04-30T12:04:11.232008Z [httpworker.13] [validation.cpp:2745] [ConnectBlock] [bench]     - Index writing: 1.22ms [0.00s (0.61ms/blk)]
 node0 2025-04-30T12:04:11.235148Z [httpworker.13] [validationinterface.cpp:249] [BlockChecked] [validation] BlockChecked: block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 state=Valid
 node0 2025-04-30T12:04:11.237768Z [httpworker.13] [validation.cpp:3183] [ConnectTip] [bench]   - Connect total: 13.37ms [0.01s (6.68ms/blk)]
 node0 2025-04-30T12:04:11.243752Z [httpworker.13] [validation.cpp:3192] [ConnectTip] [bench]   - Flush: 6.10ms [0.01s (3.05ms/blk)]
 node0 2025-04-30T12:04:11.244664Z [httpworker.13] [validation.cpp:3202] [ConnectTip] [bench]   - Writing chainstate: 0.93ms [0.00s (0.46ms/blk)]
 node0 2025-04-30T12:04:11.250592Z [httpworker.13] [validationinterface.cpp:225] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=200 txs removed=0
 node0 2025-04-30T12:04:11.254057Z [httpworker.13] [validation.cpp:2038] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false)
 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)
 node0 2025-04-30T12:04:11.262658Z [httpworker.13] [validation.cpp:3218] [ConnectTip] [bench]   - Connect postprocess: 17.90ms [0.02s (8.95ms/blk)]
 node0 2025-04-30T12:04:11.263369Z [httpworker.13] [validation.cpp:3222] [ConnectTip] [bench] - Connect block: 38.87ms [0.04s (19.44ms/blk)]
 node0 2025-04-30T12:04:11.267817Z [httpworker.13] [txmempool.cpp:700] [check] [mempool] Checking mempool with 0 transactions and 0 inputs
 node0 2025-04-30T12:04:11.273883Z [httpworker.13] [validationinterface.cpp:215] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 block height=200
 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)
 node0 2025-04-30T12:04:11.282646Z [httpworker.13] [validationinterface.cpp:187] [ActiveTipChange] [validation] ActiveTipChange: new block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 block height=200
 node0 2025-04-30T12:04:11.293558Z [scheduler] [validationinterface.cpp:225] [operator()] [validation] MempoolTransactionsRemovedForBlock: block height=200 txs removed=0
 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
 node0 2025-04-30T12:04:11.301776Z [scheduler] [validationinterface.cpp:215] [operator()] [validation] BlockConnected: block hash=0fb32ed137b0a6b939705940a67cd3c9ce56da2816403fd7ae9955929adeb581 block height=200
 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)
 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
 node0 2025-04-30T12:04:11.312059Z [httpworker.7] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__
 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
 node0 2025-04-30T12:04:11.318501Z [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=submitblock user=__cookie__
 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
 node0 2025-04-30T12:04:11.336029Z [httpworker.9] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__
 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
 node0 2025-04-30T12:04:11.338316Z [httpworker.0] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__
 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
 node0 2025-04-30T12:04:11.340445Z [httpworker.10] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getrawmempool user=__cookie__
 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
 node0 2025-04-30T12:04:11.344433Z [httpworker.15] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__
 test  2025-04-30T12:04:11.349000Z TestFramework (INFO): hook into the net:inbound_message and net:outbound_message tracepoints
 test  2025-04-30T12:04:12.884000Z TestFramework (INFO): connect a P2P test node to our bitcoind node
 test  2025-04-30T12:04:12.884000Z TestFramework.p2p (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:11000
 test  2025-04-30T12:04:12.884000Z TestFramework.p2p (DEBUG): Connected: us=127.0.0.1:47156, them=127.0.0.1:11000
 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)
 node0 2025-04-30T12:04:12.902348Z [net] [net.cpp:3833] [CNode] [net] Added connection peer=0
 node0 2025-04-30T12:04:12.906639Z [net] [net.cpp:1854] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:47156 accepted
 test  2025-04-30T12:04:13.459000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:11000
 test  2025-04-30T12:04:13.485000Z TestFramework (ERROR): Assertion failed
                                   Traceback (most recent call last):
                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/test_framework.py", line 183, in main
                                       self.run_test()
                                     File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 259, in run_test
                                       self.p2p_message_tracepoint_test()
                                     File "/home/will/src/core/bitcoin/build/test/functional/interface_usdt_net.py", line 327, in p2p_message_tracepoint_test
                                       self.nodes[0].add_p2p_connection(test_node)
                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/test_node.py", line 736, in add_p2p_connection
                                       p2p_conn.wait_for_verack()
                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 692, in wait_for_verack
                                       self.wait_until(test_function, timeout=timeout)
                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 601, in wait_until
                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor, check_interval=check_interval)
                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/util.py", line 311, in wait_until_helper_internal
                                       if predicate():
                                          ^^^^^^^^^^^
                                     File "/home/will/src/core/bitcoin/test/functional/test_framework/p2p.py", line 598, in test_function
                                       assert self.is_connected
                                              ^^^^^^^^^^^^^^^^^
                                   AssertionError
 test  2025-04-30T12:04:13.486000Z TestFramework (DEBUG): Closing down network thread
 test  2025-04-30T12:04:13.536000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
 test  2025-04-30T12:04:13.536000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250430_130404/interface_usdt_net_0
 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
 test  2025-04-30T12:04:13.536000Z TestFramework (ERROR):
 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
 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR):
 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.
 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
 test  2025-04-30T12:04:13.537000Z TestFramework (ERROR):

 node0 stderr ==307456==
==307456== Process terminating with default action of signal 5 (SIGTRAP)
==307456==    at 0x590156: ~basic_string (basic_string.h:809)
==307456==    by 0x590156: (anonymous namespace)::PeerManagerImpl::ProcessMessages(CNode*, std::atomic<bool>&) (net_processing.cpp:5040)
==307456==    by 0x543DDD: CConnman::ThreadMessageHandler() (net.cpp:3054)
==307456==    by 0xCBF40E: operator() (std_function.h:591)
==307456==    by 0xCBF40E: util::TraceThread(std::basic_string_view<char, std::char_traits<char> >, std::function<void ()>) (thread.cpp:21)
==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)
==307456==    by 0x535D56: __invoke<void (*)(std::basic_string_view<char>, std::function<void()>), char const*, CConnman::Start(CScheduler&, const Options&)::<lambda()> > (invoke.h:96)
==307456==    by 0x535D56: _M_invoke<0, 1, 2> (std_thread.h:301)
==307456==    by 0x535D56: operator() (std_thread.h:308)
==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)
==307456==    by 0x4B70123: execute_native_thread_routine (in /nix/store/7hyxhin05law4mnxsdrmqv30h0rnqdxm-gcc-14.2.0-lib/lib/libstdc++.so.6.0.33)
==307456==    by 0x4E9DD01: start_thread (in /nix/store/pacbfvpzqz2mksby36awvbcn051zcji3-glibc-2.40-36/lib/libc.so.6)
==307456==    by 0x4F1D193: clone (in /nix/store/pacbfvpzqz2mksby36awvbcn051zcji3-glibc-2.40-36/lib/libc.so.6)

</details>

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

Linked (view graph)

#5 Make the version number the protocol version and not the client version #32492 test: add skip_if_running_under_valgrind()