1 #!/usr/bin/env python3
2 # Copyright (c) 2017-present The Bitcoin Core developers
3 # Distributed under the MIT software license, see the accompanying
4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
5 """Test recovery from a crash during chainstate writing.
6 7 - 4 nodes
8 * node0, node1, and node2 will have different dbcrash ratios, and different
9 dbcache sizes
10 * node3 will be a regular node, with no crashing.
11 * The nodes will not connect to each other.
12 13 - use default test framework starting chain. initialize starting_tip_height to
14 tip height.
15 16 - Main loop:
17 * generate lots of transactions on node3, enough to fill up a block.
18 * uniformly randomly pick a tip height from starting_tip_height to
19 tip_height; with probability 1/(height_difference+4), invalidate this block.
20 * mine enough blocks to overtake tip_height at start of loop.
21 * for each node in [node0,node1,node2]:
22 - for each mined block:
23 * submit block to node
24 * if node crashed on/after submitting:
25 - restart until recovery succeeds
26 - check that utxo matches node3 using gettxoutsetinfo"""
27 28 import random
29 import time
30 31 from test_framework.blocktools import COINBASE_MATURITY
32 from test_framework.messages import (
33 COIN,
34 )
35 from test_framework.test_framework import BitcoinTestFramework
36 from test_framework.util import (
37 assert_not_equal,
38 assert_equal,
39 )
40 from test_framework.wallet import (
41 MiniWallet,
42 getnewdestination,
43 )
44 45 46 class ChainstateWriteCrashTest(BitcoinTestFramework):
47 def set_test_params(self):
48 self.num_nodes = 4
49 self.rpc_timeout = 480
50 51 # Set -maxmempool=0 to turn off mempool memory sharing with dbcache
52 self.base_args = [
53 "-maxmempool=0",
54 "-dbbatchsize=200000",
55 ]
56 57 # Set different crash ratios and cache sizes. Note that not all of
58 # -dbcache goes to the in-memory coins cache.
59 self.node0_args = ["-dbcrashratio=8", "-dbcache=4"] + self.base_args
60 self.node1_args = ["-dbcrashratio=16", "-dbcache=8"] + self.base_args
61 self.node2_args = ["-dbcrashratio=24", "-dbcache=16"] + self.base_args
62 63 # Node3 is a normal node with default args, except will mine full blocks
64 # and txs with "dust" outputs
65 self.node3_args = ["-blockmaxweight=4000000", "-dustrelayfee=0"]
66 self.extra_args = [self.node0_args, self.node1_args, self.node2_args, self.node3_args]
67 68 def setup_network(self):
69 self.add_nodes(self.num_nodes, extra_args=self.extra_args)
70 self.start_nodes()
71 # Leave them unconnected, we'll use submitblock directly in this test
72 73 def restart_node(self, node_index, *, expected_tip):
74 """Start up a given node id, wait for the tip to reach the given block hash, and calculate the utxo hash.
75 76 Exceptions during startup or subsequent RPC calls should indicate a node crash (due to -dbcrashratio), in which case we try again. Give up
77 after a timeout. Returns the utxo hash of the given node."""
78 79 time_start = time.time()
80 while time.time() - time_start < 120 * self.options.timeout_factor:
81 try:
82 # Any of these RPC calls could throw due to node crash
83 self.start_node(node_index)
84 self.nodes[node_index].waitforblock(expected_tip)
85 utxo_hash = self.nodes[node_index].gettxoutsetinfo()['hash_serialized_3']
86 return utxo_hash
87 except Exception:
88 # An exception here should mean the node is about to crash.
89 # If bitcoind exits, then try again. wait_for_node_exit()
90 # enforces that bitcoind crashed.
91 self.wait_for_node_exit(node_index, timeout=10)
92 self.crashed_on_restart += 1
93 94 # If we got here, bitcoind isn't coming back up on restart. Could be a
95 # bug in bitcoind, or we've gotten unlucky with our dbcrash ratio --
96 # perhaps we generated a test case that blew up our cache?
97 # If this happens, the test should try to restart without -dbcrashratio
98 # and make sure that recovery happens.
99 raise AssertionError(f"Unable to successfully restart node {node_index} in allotted time")
100 101 def submit_block_catch_error(self, node_index, block):
102 """Try submitting a block to the given node.
103 104 Catch any exceptions that indicate the node has crashed.
105 The caller will check that a crash happened.
106 Returns true if the block was submitted successfully; false otherwise."""
107 108 try:
109 self.nodes[node_index].submitblock(block)
110 return True
111 except Exception as e:
112 self.log.debug(f"node {node_index} submitblock raised exception: {e}")
113 return False
114 115 def sync_node3blocks(self, block_hashes):
116 """Use submitblock to sync node3's chain with the other nodes
117 118 If submitblock fails, restart the node and get the new utxo hash.
119 If any nodes crash while updating, we'll compare utxo hashes to
120 ensure recovery was successful."""
121 122 node3_utxo_hash = self.nodes[3].gettxoutsetinfo()['hash_serialized_3']
123 124 # Retrieve all the blocks from node3
125 blocks = []
126 for block_hash in block_hashes:
127 blocks.append([block_hash, self.nodes[3].getblock(block_hash, 0)])
128 129 # Deliver each block to each other node
130 for i in range(3):
131 nodei_utxo_hash = None
132 self.log.debug(f"Syncing blocks to node {i}")
133 for (block_hash, block) in blocks:
134 # Get the block from node3, and submit to node_i
135 self.log.debug(f"submitting block {block_hash}")
136 if not self.submit_block_catch_error(i, block):
137 # TODO: more carefully check that the crash is due to -dbcrashratio
138 # (change the exit code perhaps, and check that here?)
139 # wait_for_node_exit() enforces that bitcoind crashed.
140 self.wait_for_node_exit(i, timeout=30)
141 self.log.debug(f"Restarting node {i} after block hash {block_hash}")
142 nodei_utxo_hash = self.restart_node(i, expected_tip=block_hash)
143 assert nodei_utxo_hash is not None
144 self.restart_counts[i] += 1
145 else:
146 # Clear it out after successful submitblock calls -- the cached
147 # utxo hash will no longer be correct
148 nodei_utxo_hash = None
149 150 # Check that the utxo hash matches node3's utxo set
151 # NOTE: we only check the utxo set if we had to restart the node
152 # after the last block submitted:
153 # - checking the utxo hash causes a cache flush, which we don't
154 # want to do every time; so
155 # - we only update the utxo cache after a node restart, since flushing
156 # the cache is a no-op at that point
157 if nodei_utxo_hash is not None:
158 self.log.debug(f"Checking txoutsetinfo matches for node {i}")
159 assert_equal(nodei_utxo_hash, node3_utxo_hash)
160 161 def verify_utxo_hash(self):
162 """Verify that the utxo hash of each node matches node3.
163 164 Restart any nodes that crash while querying."""
165 node3_utxo_hash = self.nodes[3].gettxoutsetinfo()['hash_serialized_3']
166 self.log.info("Verifying utxo hash matches for all nodes")
167 168 for i in range(3):
169 try:
170 nodei_utxo_hash = self.nodes[i].gettxoutsetinfo()['hash_serialized_3']
171 except Exception:
172 # probably a crash on db flushing
173 self.wait_for_node_exit(i, timeout=10)
174 nodei_utxo_hash = self.restart_node(i, expected_tip=self.nodes[3].getbestblockhash())
175 assert_equal(nodei_utxo_hash, node3_utxo_hash)
176 177 def generate_small_transactions(self, node, count, utxo_list):
178 FEE = 1000
179 num_transactions = 0
180 random.shuffle(utxo_list)
181 while len(utxo_list) >= 2 and num_transactions < count:
182 utxos_to_spend = [utxo_list.pop() for _ in range(2)]
183 input_amount = int(sum([utxo['value'] for utxo in utxos_to_spend]) * COIN)
184 if input_amount < FEE:
185 # Sanity check -- if we chose inputs that are too small, skip
186 continue
187 188 tx = self.wallet.create_self_transfer_multi(
189 utxos_to_spend=utxos_to_spend,
190 num_outputs=3,
191 fee_per_output=FEE // 3,
192 )
193 node.sendrawtransaction(hexstring=tx["hex"], maxfeerate=0)
194 num_transactions += 1
195 196 def run_test(self):
197 self.wallet = MiniWallet(self.nodes[3])
198 initial_height = self.nodes[3].getblockcount()
199 self.generate(self.nodes[3], COINBASE_MATURITY, sync_fun=self.no_op)
200 201 # Track test coverage statistics
202 self.restart_counts = [0, 0, 0] # Track the restarts for nodes 0-2
203 self.crashed_on_restart = 0 # Track count of crashes during recovery
204 205 # Start by creating a lot of utxos on node3
206 utxo_list = []
207 for _ in range(5):
208 utxo_list.extend(self.wallet.send_self_transfer_multi(from_node=self.nodes[3], num_outputs=1000)['new_utxos'])
209 self.generate(self.nodes[3], 1, sync_fun=self.no_op)
210 assert_equal(len(self.nodes[3].getrawmempool()), 0)
211 self.log.info(f"Prepped {len(utxo_list)} utxo entries")
212 213 # Sync these blocks with the other nodes
214 block_hashes_to_sync = []
215 for height in range(initial_height + 1, self.nodes[3].getblockcount() + 1):
216 block_hashes_to_sync.append(self.nodes[3].getblockhash(height))
217 218 self.log.debug(f"Syncing {len(block_hashes_to_sync)} blocks with other nodes")
219 # Syncing the blocks could cause nodes to crash, so the test begins here.
220 self.sync_node3blocks(block_hashes_to_sync)
221 222 starting_tip_height = self.nodes[3].getblockcount()
223 224 # Main test loop:
225 # each time through the loop, generate a bunch of transactions,
226 # and then either mine a single new block on the tip, or some-sized reorg.
227 for i in range(40):
228 self.log.info(f"Iteration {i}, generating 2500 transactions {self.restart_counts}")
229 # Generate a bunch of small-ish transactions
230 self.generate_small_transactions(self.nodes[3], 2500, utxo_list)
231 # Pick a random block between current tip, and starting tip
232 current_height = self.nodes[3].getblockcount()
233 random_height = random.randint(starting_tip_height, current_height)
234 self.log.debug(f"At height {current_height}, considering height {random_height}")
235 if random_height > starting_tip_height:
236 # Randomly reorg from this point with some probability (1/4 for
237 # tip, 1/5 for tip-1, ...)
238 if random.random() < 1.0 / (current_height + 4 - random_height):
239 self.log.debug(f"Invalidating block at height {random_height}")
240 self.nodes[3].invalidateblock(self.nodes[3].getblockhash(random_height))
241 242 # Now generate new blocks until we pass the old tip height
243 self.log.debug("Mining longer tip")
244 block_hashes = []
245 while current_height + 1 > self.nodes[3].getblockcount():
246 block_hashes.extend(self.generatetoaddress(
247 self.nodes[3],
248 nblocks=min(10, current_height + 1 - self.nodes[3].getblockcount()),
249 # new address to avoid mining a block that has just been invalidated
250 address=getnewdestination()[2],
251 sync_fun=self.no_op,
252 ))
253 self.log.debug(f"Syncing {len(block_hashes)} new blocks...")
254 self.sync_node3blocks(block_hashes)
255 self.wallet.rescan_utxos()
256 utxo_list = self.wallet.get_utxos()
257 self.log.debug(f"MiniWallet utxo count: {len(utxo_list)}")
258 259 # Check that the utxo hashes agree with node3
260 # Useful side effect: each utxo cache gets flushed here, so that we
261 # won't get crashes on shutdown at the end of the test.
262 self.verify_utxo_hash()
263 264 # Check the test coverage
265 self.log.info(f"Restarted nodes: {self.restart_counts}; crashes on restart: {self.crashed_on_restart}")
266 267 # If no nodes were restarted, we didn't test anything.
268 assert_not_equal(self.restart_counts, [0, 0, 0])
269 270 # Make sure we tested the case of crash-during-recovery.
271 assert self.crashed_on_restart > 0
272 273 # Warn if any of the nodes escaped restart.
274 for i in range(3):
275 if self.restart_counts[i] == 0:
276 self.log.warning(f"Node {i} never crashed during utxo flush!")
277 278 279 if __name__ == "__main__":
280 ChainstateWriteCrashTest(__file__).main()
281