Skip to content

test: wallet_reorgsrestore.py failure under valgrind #32493

@fanquake

Description

@fanquake

I see this consistently when running the native_valgrind CI:

node0 2025-05-14T10:02:50.888348Z [init] [wallet/wallet.h:924] [WalletLogPrintf] [reorg_crash] Wallet completed loading in              61ms 
 node0 2025-05-14T10:02:50.889127Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.889588Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.889965Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.890780Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.891224Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.891602Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.892422Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.892865Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.893253Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.894021Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.894440Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.894808Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.895605Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.896039Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.896394Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.897229Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.897680Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.898098Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.898850Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.899271Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.899633Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.900392Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:50.900808Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:50.901176Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:50.902018Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: SELECT value FROM main WHERE key = x'0962657374626c6f636b' 
 node0 2025-05-14T10:02:50.902278Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: SELECT value FROM main WHERE key = x'1262657374626c6f636b5f6e6f6d65726b6c65' 
 node0 2025-05-14T10:02:50.903082Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: SELECT value FROM main WHERE key = x'0962657374626c6f636b' 
 node0 2025-05-14T10:02:50.903344Z [init] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: SELECT value FROM main WHERE key = x'1262657374626c6f636b5f6e6f6d65726b6c65' 
 node0 2025-05-14T10:02:50.903656Z [init] [wallet/wallet.h:924] [WalletLogPrintf] [reorg_crash] setKeyPool.size() = 8 
 node0 2025-05-14T10:02:50.903793Z [init] [wallet/wallet.h:924] [WalletLogPrintf] [reorg_crash] mapWallet.size() = 1 
 node0 2025-05-14T10:02:50.903915Z [init] [wallet/wallet.h:924] [WalletLogPrintf] [reorg_crash] m_address_book.size() = 1 
 node0 2025-05-14T10:02:50.905339Z [init] [init.cpp:1776] [AppInitMain] Setting NODE_NETWORK on non-prune mode 
 node0 2025-05-14T10:02:50.927907Z [init] [init.cpp:1886] [AppInitMain] block tree size = 228 
 node0 2025-05-14T10:02:50.928705Z [init] [init.cpp:1899] [AppInitMain] nBestHeight = 216 
 node0 2025-05-14T10:02:50.944147Z [init] [net.cpp:3168] [BindListenPort] Bound to 127.0.0.1:11000 
 node0 2025-05-14T10:02:50.949620Z [init] [noui.cpp:57] [noui_InitMessage] init message: Starting network threads… 
 node0 2025-05-14T10:02:50.967599Z [init] [net.cpp:3358] [Start] DNS seeding disabled 
 node0 2025-05-14T10:02:51.000689Z [init] [noui.cpp:57] [noui_InitMessage] init message: Done loading 
 node0 2025-05-14T10:02:51.010548Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread start 
 node0 2025-05-14T10:02:51.018558Z [initload] [util/thread.cpp:20] [TraceThread] initload thread start 
 node0 2025-05-14T10:02:51.025885Z [net] [util/thread.cpp:20] [TraceThread] net thread start 
 node0 2025-05-14T10:02:51.033665Z [msghand] [util/thread.cpp:20] [TraceThread] msghand thread start 
 node0 2025-05-14T10:02:51.040718Z [initload] [node/mempool_persist.cpp:73] [LoadMempool] Loading 0 mempool transactions from file... 
 node0 2025-05-14T10:02:51.044378Z [initload] [node/mempool_persist.cpp:145] [LoadMempool] Imported mempool transactions from file: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast 
 node0 2025-05-14T10:02:51.045906Z [initload] [util/thread.cpp:22] [TraceThread] initload thread exit 
 node0 2025-05-14T10:02:51.049424Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.050474Z [httpworker.8] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2025-05-14T10:02:51.090088Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.091232Z [httpworker.4] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 test  2025-05-14T10:02:51.148000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node0 2025-05-14T10:02:51.152352Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.155482Z [httpworker.9] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getwalletinfo user=__cookie__ 
 node0 2025-05-14T10:02:51.188559Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.189474Z [httpworker.2] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
 node0 2025-05-14T10:02:51.193212Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.194768Z [httpworker.13] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=invalidateblock user=__cookie__ 
 node0 2025-05-14T10:02:51.231913Z [httpworker.13] [validation.cpp:3052] [DisconnectTip] [bench] - Disconnect block: 18.37ms 
 node0 2025-05-14T10:02:51.247598Z [httpworker.13] [validation.cpp:2040] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false) 
 node0 2025-05-14T10:02:51.257342Z [httpworker.13] [validation.cpp:2967] [UpdateTipLog] UpdateTip: new best=5613be1333f0f3305a83b733ffb5aca47778c6d38954ca181e8a271e9a256fcf height=215 version=0x30000000 log2_work=8.754888 tx=219 date='2025-05-14T10:02:30Z' progress=1.000000 cache=0.3MiB(1txo) 
 node0 2025-05-14T10:02:51.261048Z [httpworker.13] [validationinterface.cpp:235] [BlockDisconnected] [validation] Enqueuing BlockDisconnected: block hash=52ddf4d829b618e6614f6377915b7e20e3848ec6457f61ef997a8b95182dd2a2 block height=216 
 node0 2025-05-14T10:02:51.288049Z [httpworker.13] [validation.cpp:2078] [InvalidChainFound] InvalidChainFound: invalid block=52ddf4d829b618e6614f6377915b7e20e3848ec6457f61ef997a8b95182dd2a2  height=216  log2_work=8.761551  date=2025-05-14T10:02:41Z 
 node0 2025-05-14T10:02:51.289738Z [httpworker.13] [validation.cpp:2083] [InvalidChainFound] InvalidChainFound:  current best=5613be1333f0f3305a83b733ffb5aca47778c6d38954ca181e8a271e9a256fcf  height=215  log2_work=8.754888  date=2025-05-14T10:02:30Z 
 node0 2025-05-14T10:02:51.299740Z [httpworker.13] [validationinterface.cpp:187] [ActiveTipChange] [validation] ActiveTipChange: new block hash=5613be1333f0f3305a83b733ffb5aca47778c6d38954ca181e8a271e9a256fcf block height=215 
 node0 2025-05-14T10:02:51.309128Z [scheduler] [validationinterface.cpp:235] [operator()] [validation] BlockDisconnected: block hash=52ddf4d829b618e6614f6377915b7e20e3848ec6457f61ef997a8b95182dd2a2 block height=216 
 node0 2025-05-14T10:02:51.339554Z [scheduler] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: BEGIN TRANSACTION 
 node0 2025-05-14T10:02:51.340926Z [scheduler] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:51.352258Z [scheduler] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: COMMIT TRANSACTION 
 node0 2025-05-14T10:02:51.379444Z [scheduler] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:51.383478Z [scheduler] [wallet/wallet.h:924] [WalletLogPrintf] [reorg_crash] AddToWallet a206802b6f3fb1bfc0c475cf6fdf1821fa2ffb87cf9223a58c8a62355ee831e4  update Inactive (abandoned=1) 
 node0 2025-05-14T10:02:51.384177Z [scheduler] [wallet/sqlite.cpp:55] [TraceSqlCallback] [walletdb:trace] [/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest/reorg_crash/wallet.dat] SQLite Statement: INSERT or REPLACE into main values(?, ?) 
 node0 2025-05-14T10:02:51.390525Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.392793Z [httpworker.1] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=syncwithvalidationinterfacequeue user=__cookie__ 
 node0 2025-05-14T10:02:51.404657Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.405706Z [httpworker.15] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getwalletinfo user=__cookie__ 
 node0 2025-05-14T10:02:51.414251Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.417299Z [httpworker.10] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=getblock user=__cookie__ 
 node0 2025-05-14T10:02:51.497784Z [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for /wallet/reorg_crash from 127.0.0.1:57014 
 node0 2025-05-14T10:02:51.499049Z [httpworker.12] [rpc/request.cpp:241] [parse] [rpc] ThreadRPCServer method=gettransaction user=__cookie__ 
 test  2025-05-14T10:02:51.629000Z TestFramework.node0 (DEBUG): Node stopped 
 test  2025-05-14T10:02:51.629000Z TestFramework.utils (DEBUG): Deleting leftover cookie file 
 test  2025-05-14T10:02:51.630000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 test  2025-05-14T10:02:55.888000Z TestFramework (ERROR): Unexpected exception caught during testing 
                                   Traceback (most recent call last):
                                     File "/ci_container_base/test/functional/test_framework/test_framework.py", line 183, in main
                                       self.run_test()
                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/wallet_reorgsrestore.py", line 214, in run_test
                                       self.test_reorg_handling_during_unclean_shutdown()
                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/wallet_reorgsrestore.py", line 119, in test_reorg_handling_during_unclean_shutdown
                                       self.start_node(0)
                                     File "/ci_container_base/test/functional/test_framework/test_framework.py", line 583, in start_node
                                       node.wait_for_rpc_connection()
                                     File "/ci_container_base/test/functional/test_framework/test_node.py", line 275, in wait_for_rpc_connection
                                       raise FailedToStartError(self._node_msg(
                                   test_framework.test_node.FailedToStartError: [node 0] bitcoind exited with status 1 during initialization. Error: Cannot obtain a lock on directory /tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest. Bitcoin Core is probably already running.
                                   ************************
 test  2025-05-14T10:02:55.890000Z TestFramework (DEBUG): Closing down network thread 
 test  2025-05-14T10:02:55.941000Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later. 
 test  2025-05-14T10:02:55.941000Z TestFramework (WARNING): Not cleaning up dir /tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0 
 test  2025-05-14T10:02:55.941000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/test_framework.log 
 test  2025-05-14T10:02:55.941000Z TestFramework (ERROR): 
 test  2025-05-14T10:02:55.941000Z TestFramework (ERROR): Hint: Call /ci_container_base/test/functional/combine_logs.py '/tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0' to consolidate all logs 
 test  2025-05-14T10:02:55.941000Z TestFramework (ERROR): 
 test  2025-05-14T10:02:55.942000Z 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-05-14T10:02:55.942000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues 
 test  2025-05-14T10:02:55.942000Z TestFramework (ERROR): 
 node0 2025-05-14T10:03:36.019830Z [scheduler] [net.cpp:2427] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 

 node0 stderr Error: Cannot obtain a lock on directory /tmp/test_runner_₿_🏃_20250514_100134/wallet_reorgsrestore_0/node0/regtest. Bitcoin Core is probably already running.

Looks similar to #32066, which was fixed in #32069. cc @furszy @mzumsande.

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions