Intermittent issue in feature_assumeutxo.py", line 629, in run_test assert not self.has_blockfile(n1, “00002”), “too many blockfiles” #33635

issue maflcko openend this issue on October 15, 2025
  1. maflcko commented at 7:15 pm on October 15, 2025: member

    Seen locally in https://drahtbot.space/temp_scratch/feature_assumeutxo_265.tar.zstd:

    commit should be roughly 40e7d4cd0d7f1d922b92b0c640d3d89eef059411 and the command was RUN_UNIT_TESTS=false MAKEJOBS="-j8" FILE_ENV="./ci/test/00_setup_env_native_nowallet_libbitcoinkernel.sh" ./ci/test_run_all.sh

     0 node1 2025-10-15T18:56:48.763939Z [shutoff] [txdb.cpp:151] [virtual bool CCoinsViewDB::BatchWrite(CoinsViewCacheCursor &, const uint256 &)] [coindb] Writing final batch of 0.00 MiB 
 1 node1 2025-10-15T18:56:48.763948Z [shutoff] [txdb.cpp:153] [virtual bool CCoinsViewDB::BatchWrite(CoinsViewCacheCursor &, const uint256 &)] [coindb] Committed 0 changed transaction outputs (out of 0) to coin database... 
 2 node1 2025-10-15T18:56:48.763958Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write coins cache to disk (0 coins, 256KiB) completed (0.02ms) 
 3 node1 2025-10-15T18:56:48.763966Z [shutoff] [validationinterface.cpp:246] [void ValidationSignals::ChainStateFlushed(ChainstateRole, const CBlockLocator &)] [validation] Enqueuing ChainStateFlushed: block hash=5d3144f90878dbabd3a42352be3294df923c93198e1399b93d07292c9cd1e1ce 
 4 node1 2025-10-15T18:56:48.763997Z [shutoff] [validation.cpp:2837] [bool Chainstate::FlushStateToDisk(BlockValidationState &, FlushStateMode, int)] [coindb] Writing chainstate to disk: flush mode=ALWAYS, prune=0, large=0, critical=0, periodic=0 
 5 node1 2025-10-15T18:56:48.764007Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write block and undo data to disk started 
 6 node1 2025-10-15T18:56:48.764041Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write block and undo data to disk completed (0.03ms) 
 7 node1 2025-10-15T18:56:48.764050Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write block index to disk started 
 8 node1 2025-10-15T18:56:48.764061Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write block index to disk completed (0.01ms) 
 9 node1 2025-10-15T18:56:48.764067Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write coins cache to disk (0 coins, 256KiB) started 
10 node1 2025-10-15T18:56:48.764076Z [shutoff] [txdb.cpp:151] [virtual bool CCoinsViewDB::BatchWrite(CoinsViewCacheCursor &, const uint256 &)] [coindb] Writing final batch of 0.00 MiB 
11 node1 2025-10-15T18:56:48.764083Z [shutoff] [txdb.cpp:153] [virtual bool CCoinsViewDB::BatchWrite(CoinsViewCacheCursor &, const uint256 &)] [coindb] Committed 0 changed transaction outputs (out of 0) to coin database... 
12 node1 2025-10-15T18:56:48.764092Z [shutoff] [logging/timer.h:58] [void BCLog::Timer<std::chrono::duration<long long, std::ratio<1, 1000>>>::Log(const std::string &) [TimeType = std::chrono::duration<long long, std::ratio<1, 1000>>]] [bench] FlushStateToDisk: write coins cache to disk (0 coins, 256KiB) completed (0.02ms) 
13 node1 2025-10-15T18:56:48.764100Z [shutoff] [validationinterface.cpp:246] [void ValidationSignals::ChainStateFlushed(ChainstateRole, const CBlockLocator &)] [validation] Enqueuing ChainStateFlushed: block hash=6d9186a0db6df121d2006c40c7827c447afe6329b705666bca1744b72c71f0ad 
14 node1 2025-10-15T18:56:48.767027Z [shutoff] [init.cpp:410] [void Shutdown(NodeContext &)] Shutdown done 
15 test  2025-10-15T18:56:48.791717Z TestFramework.node1 (DEBUG): Node stopped 
16 test  2025-10-15T18:56:48.791816Z TestFramework (INFO): Checking that blocks are segmented on disk 
17 test  2025-10-15T18:56:48.791990Z TestFramework (ERROR): Unexpected exception 
18                                   Traceback (most recent call last):
19                                     File "/ci_container_base/test/functional/test_framework/test_framework.py", line 198, in main
20                                       self.run_test()
21                                     File "/ci_container_base/ci/scratch/build-x86_64-pc-linux-gnu/test/functional/feature_assumeutxo.py", line 629, in run_test
22                                       assert not self.has_blockfile(n1, "00002"), "too many blockfiles"
23                                   AssertionError: too many blockfiles
  2. maflcko added the label CI failed on Oct 15, 2025
  3. b-l-u-e commented at 2:30 pm on January 26, 2026: contributor

    Seen locally in https://drahtbot.space/temp_scratch/feature_assumeutxo_265.tar.zstd:

    i tried studying from the report shared above realized that maybe the assertion assert not self.has_blockfile(n1, "00002") was too strict perhaps maybe we can condition it because segmentation works as expected

    coz with -fastprune it does 64KB blockfiles… coz node1 runs two chainstates concurrently NORMAL and ASSUMED…so this segmentation keeps their blocks separate

    so when NORMAL syncs enough blocks to fill blk00000.dat it creates blk00002.dat

    from node1/regtest/debug.log

    0[assumed] initializing blockfile cursor to BlockfileCursor(file_num=1)
1...
2Leaving block file 0: CBlockFileInfo(blocks=242, size=65331, heights=0...240) (onto 2) (height 241)

    i think or rather maybe test should verify segmentation works blk00001.dat exists for ASSUMED blocks not just limit to 2 files

  4. maflcko commented at 6:23 pm on January 27, 2026: member
    I think this is -stopatheight not working?
  5. maflcko commented at 6:26 pm on January 27, 2026: member

    Hmmm, maybe not, because this diff is passing:

     0diff --git a/test/functional/feature_assumeutxo.py b/test/functional/feature_assumeutxo.py
 1index 20ebd823d1..959b3bbd9a 100755
 2--- a/test/functional/feature_assumeutxo.py
 3+++ b/test/functional/feature_assumeutxo.py
 4@@ -606,7 +606,7 @@ class AssumeutxoTest(BitcoinTestFramework):
 5         assert signed_txid in n1.getrawmempool()
 6         assert not n1.gettxout(prev_tx['txid'], 0)
 7 
 8-        PAUSE_HEIGHT = FINAL_HEIGHT - 40
 9+        PAUSE_HEIGHT = FINAL_HEIGHT 
10 
11         self.log.info("Restarting node to stop at height %d", PAUSE_HEIGHT)
12         self.restart_node(1, extra_args=[
  6. maflcko commented at 9:42 am on January 29, 2026: member

    I tried to reproduce this with the command below, but failed. I guess this fixed itself?

    while ( TEST_RUNNER_EXTRA="$( for i in {1..400}; do echo -n "feature_assumeutxo.py "; done )" RUN_UNIT_TESTS=false MAKEJOBS="-j8" FILE_ENV="./ci/test/00_setup_env_native_nowallet.sh" ./ci/test_run_all.sh ) ; do echo _ >> /tmp/runs ; done

  7. maflcko closed this on Jan 29, 2026
  8. maflcko commented at 10:00 am on January 29, 2026: member

    Nvm. It happened again after a few thousand iterations:

    https://drahtbot.space/temp_scratch/feature_assumeutxo_201.tar.zstd

  9. maflcko reopened this on Jan 29, 2026
  10. maflcko commented at 2:22 pm on January 30, 2026: member

    i tried studying from the report shared above realized that maybe the assertion assert not self.has_blockfile(n1, "00002") was too strict perhaps maybe we can condition it because segmentation works as expected

    coz with -fastprune it does 64KB blockfiles… coz node1 runs two chainstates concurrently NORMAL and ASSUMED…so this segmentation keeps their blocks separate

    so when NORMAL syncs enough blocks to fill blk00000.dat it creates blk00002.dat

    from node1/regtest/debug.log

    0[assumed] initializing blockfile cursor to BlockfileCursor(file_num=1)
1...
2Leaving block file 0: CBlockFileInfo(blocks=242, size=65331, heights=0...240) (onto 2) (height 241)

    Thanks for taking a look. I am primarily interested in why this is happening intermittently. Usually this happens due to one thread being slower than another. For example in #34425, a sleep added in the right place will make a particular intermittent issue appear more deterministically:

    0diff --git a/src/net.cpp b/src/net.cpp
1index 6b79e913e8..32bd061500 100644
2--- a/src/net.cpp
3+++ b/src/net.cpp
4@@ -2200,2 +2200,3 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
5                 }
6+            UninterruptibleSleep(599ms);
7                 pnode->CloseSocketDisconnect();

    I’d be great to find a diff to make this one reproduce deterministically as well.

  11. b-l-u-e commented at 2:51 pm on January 30, 2026: contributor

    i tried studying from the report shared above realized that maybe the assertion assert not self.has_blockfile(n1, "00002") was too strict perhaps maybe we can condition it because segmentation works as expected coz with -fastprune it does 64KB blockfiles… coz node1 runs two chainstates concurrently NORMAL and ASSUMED…so this segmentation keeps their blocks separate so when NORMAL syncs enough blocks to fill blk00000.dat it creates blk00002.dat from node1/regtest/debug.log

    0[assumed] initializing blockfile cursor to BlockfileCursor(file_num=1)
1...
2Leaving block file 0: CBlockFileInfo(blocks=242, size=65331, heights=0...240) (onto 2) (height 241)

    Thanks for taking a look. I am primarily interested in why this is happening intermittently. Usually this happens due to one thread being slower than another. For example in #34425, a sleep added in the right place will make a particular intermittent issue appear more deterministically:

    0diff --git a/src/net.cpp b/src/net.cpp
1index 6b79e913e8..32bd061500 100644
2--- a/src/net.cpp
3+++ b/src/net.cpp
4@@ -2200,2 +2200,3 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
5                 }
6+            UninterruptibleSleep(599ms);
7                 pnode->CloseSocketDisconnect();

    I’d be great to find a diff to make this one reproduce deterministically as well.

    Let me try to add a sleep between when NORMAL and ASSUMED chainstates start the syncing

  12. b-l-u-e commented at 8:05 pm on February 3, 2026: contributor

    I’d be great to find a diff to make this one reproduce deterministically as well.

    so i did a test repro run by adding a sleep in ConnectTip() for the snapshot chainstate slows it down giving the normal chainstate time to fill blk00000.dat and roll to blk00002.dat before -stopatheight triggers

     0diff --git a/src/validation.cpp b/src/validation.cpp
 1--- a/src/validation.cpp
 2+++ b/src/validation.cpp
 3@@ -3079,6 +3079,10 @@ bool Chainstate::ConnectTip(...)
 4     {
 5         CCoinsViewCache& view{*m_coins_views->m_connect_block_view};
 6         const auto reset_guard{view.CreateResetGuard()};
 7+        if (m_from_snapshot_blockhash) {
 8+            UninterruptibleSleep(std::chrono::milliseconds{120});
 9+        }
10         bool rv = ConnectBlock(*block_to_connect, state, pindexNew, view);

    and also i made change infeature_assumeutxo.py with a 10s wait_until_stopped so as the slowed snapshot can reach -stopatheight).

     0diff --git a/test/functional/feature_assumeutxo.py b/test/functional/feature_assumeutxo.py
 1--- a/test/functional/feature_assumeutxo.py
 2+++ b/test/functional/feature_assumeutxo.py
 3@@ -644,15 +644,12 @@ class AssumeutxoTest(BitcoinTestFramework):
 4         # assertions and the -stopatheight tripping.
 5         self.connect_nodes(0, 1, wait_for_connect=False)
 6 
 7-        n1.wait_until_stopped(timeout=5)
 8+        n1.wait_until_stopped(timeout=10)  
 9 
10         self.log.info("Checking that blocks are segmented on disk")
11         assert self.has_blockfile(n1, "00000"), "normal blockfile missing"
12         assert self.has_blockfile(n1, "00001"), "assumed blockfile missing"
13         assert not self.has_blockfile(n1, "00002"), "too many blockfiles"
14 
15         self.log.info("Restarted node before snapshot validation completed, reloading...")
16         self.restart_node(1, extra_args=self.extra_args[1])
    • and i run with --nocleanup --tmpdir=/tmp/bitcoin_test_assumeutxo_repro to see the results
    0/tmp/bitcoin_test_assumeutxo_repro/node1/regtest/blocks/
1blk00000.dat  65331 bytes  (filled normal chainstate)
2blk00001.dat  32768 bytes  (snapshot chainstate)
3blk00002.dat  32768 bytes  (normal chainstate rollover)
    • so with -fastprune, blockfiles are 64 KiB
    • the sleep delays the snapshot chainstate from reaching -stopatheight=359
    • while also the background chainstate fills the 64 KiB blockfile
    • so when its full, it rolls to blk00002.dat since blk00001.dat is reserved for snapshot


maflcko b-l-u-e

Labels
CI failed

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-02-17 12:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me