"txospenderindex_tests/txospenderindex_initial_sync": critical check tx_spender->has_value() has failed

[fanquake]

https://github.com/bitcoin/bitcoin/actions/runs/22227876457/job/64299801435?pr=34615#step:8:652

./test/txospenderindex_tests.cpp(15): Entering test case "txospenderindex_initial_sync"
./test/txospenderindex_tests.cpp(60): fatal error: in "txospenderindex_tests/txospenderindex_initial_sync": critical check tx_spender->has_value() has failed
Command '['./bin/test_bitcoin.exe', '-l', 'test_suite']' returned non-zero exit status 3221225477.

[hodlinator]

Notable that it only happens on Windows UCRT in the linked run, indicating probable insufficient synchronization between txospenderindex and the new block in chainstate. Maybe we should move SyncWithValidationInterfaceQueue() before the failing check?

[sedited]

Maybe we should move SyncWithValidationInterfaceQueue() before the failing check?

BlockUntilSyncedToCurrentChain() should already be doing that. It's a bit puzzling, I also couldn't reproduce a failure after 10'000 test runs.

[w0xlt]

BlockUntilSyncedToCurrentChain() wouldn't catch this. After Sync(), both best_block_index and chain_tip are at block 151, so it takes the early return without draining the queue:

  if (best_block_index->GetAncestor(chain_tip->nHeight) == chain_tip) {
      return true;  // skips SyncWithValidationInterfaceQueue()
  }

The issue looks to be that 51 BlockConnected callbacks (for blocks mined between Init() and Sync()) are still pending in the validation interface queue. When the scheduler delivers the stale callbacks and BlockConnected sees best_block_index=151 but receives a notification for pindex=101, it interprets this as: "I'm at 151, but I need to process block 101 — I must have missed something, let me rewind to block 100 and re-index from there." That rewind erases the spending entries for blocks 101-151.

if (best_block_index != pindex->pprev && !Rewind(best_block_index, pindex->pprev)) {

On Linux the scheduler seems to drain those callbacks before Sync() sets m_synced = true. But the error can be deterministically triggered by firing a stale BlockConnected directly after Sync():

diff

diff --git a/src/test/txospenderindex_tests.cpp b/src/test/txospenderindex_tests.cpp
index 889ef7ff8a..fef331afe4 100644
--- a/src/test/txospenderindex_tests.cpp
+++ b/src/test/txospenderindex_tests.cpp
@@ -4,7 +4,10 @@
 
 #include <chainparams.h>
 #include <index/txospenderindex.h>
+#include <kernel/types.h>
+#include <node/blockstorage.h>
 #include <test/util/setup_common.h>
+#include <test/util/validation.h>
 #include <util/time.h>
 #include <validation.h>
 
@@ -54,6 +57,24 @@ BOOST_FIXTURE_TEST_CASE(txospenderindex_initial_sync, TestChain100Setup)
     BOOST_CHECK(!txospenderindex.BlockUntilSyncedToCurrentChain());
 
     txospenderindex.Sync();
+
+    // Simulate a stale BlockConnected callback: fire BlockConnected for block
+    // 101, which Sync() already indexed. Since m_synced is now true, this
+    // triggers Rewind(tip, 100), erasing spending entries for blocks 101-tip.
+    // This reproduces the race in issue #34637 deterministically.
+    {
+        const CBlockIndex* stale_pindex;
+        {
+            LOCK(cs_main);
+            stale_pindex = m_node.chainman->ActiveChain()[101];
+        }
+        CBlock stale_block;
+        m_node.chainman->ActiveChainstate().m_blockman.ReadBlock(stale_block, *stale_pindex);
+        auto shared_block = std::make_shared<CBlock>(stale_block);
+        ValidationInterfaceTest::BlockConnected(
+            kernel::ChainstateRole{}, txospenderindex, shared_block, stale_pindex);
+    }
+
     for (size_t i = 0; i < spent.size(); i++) {
         const auto tx_spender{txospenderindex.FindSpender(spent[i])};
         BOOST_REQUIRE(tx_spender.has_value());

Adding SyncWithValidationInterfaceQueue() after Sync() to unconditionally drain the stale callbacks before querying the index should work, as observed by @hodlinator .

diff

diff --git a/src/test/txospenderindex_tests.cpp b/src/test/txospenderindex_tests.cpp
index 889ef7ff8a..4aaa5513de 100644
--- a/src/test/txospenderindex_tests.cpp
+++ b/src/test/txospenderindex_tests.cpp
@@ -54,6 +54,12 @@ BOOST_FIXTURE_TEST_CASE(txospenderindex_initial_sync, TestChain100Setup)
     BOOST_CHECK(!txospenderindex.BlockUntilSyncedToCurrentChain());
 
     txospenderindex.Sync();
+
+    // Drain stale BlockConnected callbacks that were enqueued for blocks created
+    // between Init() and Sync(). After Sync() sets m_synced = true, these
+    // callbacks can trigger unnecessary rewinds until fully processed.
+    m_node.validation_signals->SyncWithValidationInterfaceQueue();
+
     for (size_t i = 0; i < spent.size(); i++) {
         const auto tx_spender{txospenderindex.FindSpender(spent[i])};
         BOOST_REQUIRE(tx_spender.has_value());

[furszy]

Oh, just realized your comment w0xlt. I have been cooking some deep index changes to completely eradicate the underlying problem with BlockUntilSyncedToCurrentChain(), not only to fix the test. Still in draft and not ready branch.

But.. I got sidetracked today by the new txospender tests code and ended up cleaning them up. They weren't easy to read or work with. So I pushed #34653 to make our future selves' and future devs' lives easier (hopefully).

This isn’t blocking the direct test fix you are suggesting. I will happily ACK that too. Just sharing an update that there is more here, and will be pushing a new PR "soon".

[hebasto]

Notable that it only happens on Windows UCRT...

Here is the log for MSVCRT: https://github.com/bitcoin/bitcoin/actions/runs/22237824844/job/64344924186?pr=33974.

[achow101]

To clarify, does #34653 fix this issue?

[furszy]

To clarify, does #34653 fix this issue?

Yes. #34653 drains the validation queue before constructing the index, so no lagging notification will arrive during the post-Sync() checks. It also introduces a post-Sync() assertion that ensures the index is fully synced and did not abort prematurely before the checks are run.

Extra fun fact: I did this without thinking about the issue. I was just focused on cleaning up the test first. So.. would say that we should clean up code more often.

Updated #34653 description saying this is fixed there.

[achow101]

Was able to actually reproduce the issue with

diff --git a/src/index/base.cpp b/src/index/base.cpp
index fba2f4f6c10..571347d42f1 100644
--- a/src/index/base.cpp
+++ b/src/index/base.cpp
@@ -49,6 +49,12 @@ constexpr uint8_t DB_BEST_BLOCK{'B'};
 constexpr auto SYNC_LOG_INTERVAL{30s};
 constexpr auto SYNC_LOCATOR_WRITE_INTERVAL{30s};
 
+std::atomic<bool> g_debug_waiting{false};
+std::atomic<bool> g_debug_continue{false};
+std::mutex g_debug_mutex;
+std::condition_variable g_debug_cv;
+Mutex g_index_mutex;
+
 template <typename... Args>
 void BaseIndex::FatalErrorf(util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
 {
@@ -200,6 +206,16 @@ bool BaseIndex::ProcessBlock(const CBlockIndex* pindex, const CBlock* block_data
 
 void BaseIndex::Sync()
 {
+    LOCK(g_index_mutex);
+
+    {
+        g_debug_continue = false;
+        g_debug_waiting = true;
+        std::unique_lock<std::mutex> lock(g_debug_mutex);
+        g_debug_cv.wait_for(lock, std::chrono::seconds(2), [] { return g_debug_continue.load(); });
+        g_debug_waiting = false;
+    }
+
     const CBlockIndex* pindex = m_best_block_index.load();
     if (!m_synced) {
         auto last_log_time{NodeClock::now()};
@@ -327,6 +343,14 @@ bool BaseIndex::Rewind(const CBlockIndex* current_tip, const CBlockIndex* new_ti
 
 void BaseIndex::BlockConnected(const ChainstateRole& role, const std::shared_ptr<const CBlock>& block, const CBlockIndex* pindex)
 {
+    UninterruptibleSleep(100ms);
+    if (g_debug_waiting) {
+        g_debug_continue = true;
+        g_debug_cv.notify_all();
+    }
+
+    LOCK(g_index_mutex);
+
     // Ignore events from not fully validated chains to avoid out-of-order indexing.
     //
     // TODO at some point we could parameterize whether a particular index can be

[hebasto]

On NetBSD 10.1: https://github.com/hebasto/bitcoin-core-nightly/actions/runs/22336622975/job/64630655628.