Assertion `setBlockIndexCandidates.count(pindex)' failed

maflcko commented at 7:44 pm on July 23, 2019: member

This happened on travis as part of a pull request that only modified ATMP logic. So the assertion can likely also be hit on a clean master.

https://travis-ci.org/bitcoin/bitcoin/jobs/562128739#L4513 (in rpc_invalidateblock.py)

maflcko commented at 8:12 pm on July 23, 2019: member

Rerunning on the same commit passes: https://travis-ci.org/bitcoin/bitcoin/jobs/562756024, so this is indeed intermittent.

maflcko commented at 6:54 pm on July 24, 2019: member

More of those assertions incoming: https://travis-ci.org/bitcoin/bitcoin/jobs/563191235#L4660

So this happened in a recent commit, it seems.

sdaftuar commented at 9:11 pm on July 24, 2019: member

Hypothesis: #15402 broke the consistency requirements of setBlockIndexCandidates in InvalidateBlock, because we let go of cs_main between disconnecting blocks and adding entries to setBlockIndexCandidates. So CheckBlockIndex() could fail if invoked in-between those two things happening. Then #16194 came along and added a CheckBlockIndex() call to a place it didn’t exist before, namely when an invalid header is received from a peer. This can happen in a race with InvalidateBlock() in the rpc_invalidateblock test, because we use connect_nodes_bi to connect node0 with node1, resulting in two block announcements for the same set of blocks from node1 to node0.

If that guess is correct, then I think we should either decide on some new relaxed consistency requirement, if someone can come up with a reasonable justification (I haven’t tried yet), or re-work InvalidateBlock() to keep setBlockIndexCandidates in sync with the current chain tip at all times (perhaps by adding things that will eventually need to be added at the beginning, rather than at the end, but I’d need to give that more thought as well).

maflcko added this to the milestone 0.19.0 on Aug 24, 2019

maflcko added the label Bug on Aug 24, 2019

maflcko added the label Validation on Aug 24, 2019

laanwj referenced this in commit cd737214ce on Sep 16, 2019

sidhujag referenced this in commit f9a3ff0065 on Sep 16, 2019

Sjors commented at 10:12 am on September 30, 2019: member

I hit a different assertion recently while testing #16899 (utxo snapshots): Assertion failed: (!setBlockIndexCandidates.empty()), function PruneBlockIndexCandidates, file validation.cpp, line 2658.

This happened after I wound back the chain to block 570000, and then somehow the chain started moving forward to the tip, which I interrupted by calling invalidate again, etc. Not entirely sure what happened, I also got the timeout error described in #16979. But the end result was that gettxoutsetinfo returned when it reached the tip. And the next time I started the node I got this assertion.

I’m not sure if this is related, so I created #16993.

Sjors commented at 2:48 pm on September 30, 2019: member

I was hoping to test @sdaftuar’s hypothesis in the wild by having a mainnet node with lots of peers run with -checkblockindex=1 and then rewinding the chain. However this is non trivial. Peers get banned during the rollback (whitelist=0.0.0.0/0 doesn’t help) and -checkblockindex=1 causes the node to freeze when I go back to tip, see #16998.

maflcko closed this on Oct 2, 2019

maflcko commented at 2:11 pm on March 11, 2020: member

This is still happening in rpc_invalidateblock:

https://travis-ci.org/github/bitcoin/bitcoin/jobs/660672084#L6188

0 node1 stderr bitcoind: validation.cpp:4854: void CChainState::CheckBlockIndex(const Consensus::Params &): Assertion `setBlockIndexCandidates.count(pindex)' failed.

maflcko reopened this on Mar 11, 2020

maflcko removed this from the milestone 0.19.0 on Apr 24, 2020

maflcko commented at 2:38 pm on May 14, 2020: member

Still failing:

https://travis-ci.org/github/bitcoin/bitcoin/jobs/686945073#L6217

0 node1 stderr bitcoind: validation.cpp:4859: void CChainState::CheckBlockIndex(const Consensus::Params &): Assertion `setBlockIndexCandidates.count(pindex)' failed.

maflcko closed this on Mar 8, 2021

vijaydasmp referenced this in commit c1060026d1 on Dec 6, 2021

vijaydasmp referenced this in commit 63b39a1f65 on Dec 10, 2021

vijaydasmp referenced this in commit 68a010f4ff on Dec 13, 2021

vijaydasmp referenced this in commit 3bc73a2abf on Dec 13, 2021

vijaydasmp referenced this in commit bff9273316 on Dec 15, 2021

bitcoin locked this on Aug 18, 2022

bitcoin unlocked this on Jan 4, 2023

maflcko commented at 11:32 am on January 4, 2023: member

On master as of last week https://cirrus-ci.com/task/6436681495085056?logs=ci#L5232 :

 0 node1 2022-12-25T10:45:50.907549Z [httpworker.3] [validationinterface.cpp:242] [BlockDisconnected] [validation] Enqueuing BlockDisconnected: block hash=16f088ff4289a960faf08c7579c9f21d51bf3badc7f791bb793a6911ea649ebb block height=14 
 1 node1 2022-12-25T10:45:50.907585Z [httpworker.3] [validation.cpp:1601] [InvalidChainFound] InvalidChainFound: invalid block=16f088ff4289a960faf08c7579c9f21d51bf3badc7f791bb793a6911ea649ebb  height=14  log2_work=4.906891  date=2022-12-25T10:45:54Z 
 2 node1 2022-12-25T10:45:50.907593Z [httpworker.3] [validation.cpp:1606] [InvalidChainFound] InvalidChainFound:  current best=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da  height=13  log2_work=4.807355  date=2022-12-25T10:45:53Z 
 3 node1 2022-12-25T10:45:50.907954Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:53444 
 4 node1 2022-12-25T10:45:50.907988Z [httpworker.1] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=invalidateblock user=__cookie__ 
 5 node1 2022-12-25T10:45:50.908059Z [httpworker.1] [validation.cpp:2632] [DisconnectTip] [bench] - Disconnect block: 0.02ms 
 6 node1 2022-12-25T10:45:50.908076Z [httpworker.1] [validation.cpp:2546] [UpdateTipLog] UpdateTip: new best=2bd6394602012af268e92aa096393c635970ef1236801a57e66595dfdc53d90e height=12 version=0x20000000 log2_work=4.700440 tx=13 date='2022-12-25T10:45:53Z' progress=1.000000 cache=0.0MiB(16txo) 
 7 node1 2022-12-25T10:45:50.908084Z [httpworker.1] [validationinterface.cpp:242] [BlockDisconnected] [validation] Enqueuing BlockDisconnected: block hash=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da block height=13 
 8 node1 2022-12-25T10:45:50.908102Z [httpworker.1] [validation.cpp:1601] [InvalidChainFound] InvalidChainFound: invalid block=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da  height=13  log2_work=4.807355  date=2022-12-25T10:45:53Z 
 9 node1 2022-12-25T10:45:50.908110Z [httpworker.1] [validation.cpp:1606] [InvalidChainFound] InvalidChainFound:  current best=2bd6394602012af268e92aa096393c635970ef1236801a57e66595dfdc53d90e  height=12  log2_work=4.700440  date=2022-12-25T10:45:53Z 
10 node1 2022-12-25T10:45:50.908487Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:53444 
11 node1 2022-12-25T10:45:50.908518Z [httpworker.2] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
12 node1 2022-12-25T10:45:50.908855Z [http] [httpserver.cpp:239] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:53444 
13 node1 2022-12-25T10:45:50.908886Z [httpworker.0] [rpc/request.cpp:179] [parse] [rpc] ThreadRPCServer method=reconsiderblock user=__cookie__ 
14 node1 2022-12-25T10:45:50.908940Z [httpworker.0] [validation.cpp:2751] [ConnectTip] [bench]   - Load block from disk: 0.03ms [0.00s (0.01ms/blk)] 
15 node1 2022-12-25T10:45:50.908952Z [httpworker.0] [validation.cpp:2068] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
16 node1 2022-12-25T10:45:50.908962Z [httpworker.0] [validation.cpp:2170] [ConnectBlock] [bench]     - Fork checks: 0.01ms [0.00s (0.01ms/blk)] 
17 node1 2022-12-25T10:45:50.908971Z [httpworker.0] [validation.cpp:2260] [ConnectBlock] [bench]       - Connect 1 transactions: 0.01ms (0.007ms/tx, 0.000ms/txin) [0.00s (0.01ms/blk)] 
18 node1 2022-12-25T10:45:50.908988Z [httpworker.0] [validation.cpp:2278] [ConnectBlock] [bench]     - Verify 0 txins: 0.03ms (0.000ms/txin) [0.00s (0.02ms/blk)] 
19 node1 2022-12-25T10:45:50.908995Z [httpworker.0] [validation.cpp:2292] [ConnectBlock] [bench]     - Write undo data: 0.01ms [0.00s (0.01ms/blk)] 
20 node1 2022-12-25T10:45:50.909001Z [httpworker.0] [validation.cpp:2307] [ConnectBlock] [bench]     - Index writing: 0.01ms [0.00s (0.00ms/blk)] 
21 node1 2022-12-25T10:45:50.909008Z [httpworker.0] [validationinterface.cpp:255] [BlockChecked] [validation] BlockChecked: block hash=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da state=Valid 
22 node1 2022-12-25T10:45:50.909015Z [httpworker.0] [validation.cpp:2767] [ConnectTip] [bench]   - Connect total: 0.08ms [0.00s (0.04ms/blk)] 
23 node1 2022-12-25T10:45:50.909021Z [httpworker.0] [validation.cpp:2776] [ConnectTip] [bench]   - Flush: 0.01ms [0.00s (0.00ms/blk)] 
24 node1 2022-12-25T10:45:50.909028Z [httpworker.0] [validation.cpp:2786] [ConnectTip] [bench]   - Writing chainstate: 0.01ms [0.00s (0.00ms/blk)] 
25 node1 2022-12-25T10:45:50.909042Z [httpworker.0] [validation.cpp:2546] [UpdateTipLog] UpdateTip: new best=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da height=13 version=0x20000000 log2_work=4.807355 tx=14 date='2022-12-25T10:45:53Z' progress=1.000000 cache=0.0MiB(16txo) 
26 node1 2022-12-25T10:45:50.909048Z [httpworker.0] [validation.cpp:2802] [ConnectTip] [bench]   - Connect postprocess: 0.02ms [0.01s (0.24ms/blk)] 
27 node1 2022-12-25T10:45:50.909054Z [httpworker.0] [validation.cpp:2806] [ConnectTip] [bench] - Connect block: 0.14ms [0.01s (0.29ms/blk)] 
28 node1 2022-12-25T10:45:50.909060Z [httpworker.0] [txmempool.cpp:658] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
29 node1 2022-12-25T10:45:50.909068Z [httpworker.0] [validationinterface.cpp:232] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da block height=13 
30 node1 2022-12-25T10:45:50.909076Z [httpworker.0] [validationinterface.cpp:204] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=1d468aa9111562d5eea05da733b4f1ad848ba19d64a48a922b9bb9e2cdf469da fork block hash=2bd6394602012af268e92aa096393c635970ef1236801a57e66595dfdc53d90e (in IBD=false) 
31
32 node1 stderr bitcoind: validation.cpp:4648: void Chainstate::CheckBlockIndex(): Assertion `setBlockIndexCandidates.count(pindex)' failed.

maflcko reopened this on Jan 4, 2023

mzumsande commented at 5:58 pm on July 18, 2024: contributor

While #16849 fixed inconsistencies in invalidateblock, failures continued because similar inconsistencies can also happen during reconsiderblock. See #30479 for an explanation and a fix.

Assertion `setBlockIndexCandidates.count(pindex)’ failed #16444