feature_init.py raw
1 #!/usr/bin/env python3
2 # Copyright (c) 2021-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 """Tests related to node initialization."""
6 from concurrent.futures import ThreadPoolExecutor
7 from pathlib import Path
8 import os
9 import platform
10 import shutil
11 import signal
12 import subprocess
13
14 from test_framework.test_framework import BitcoinTestFramework
15 from test_framework.test_node import (
16 BITCOIN_PID_FILENAME_DEFAULT,
17 ErrorMatch,
18 )
19 from test_framework.util import assert_equal
20
21 ALL_INDEX_ARGS = [
22 '-txindex=1',
23 '-blockfilterindex=1',
24 '-coinstatsindex=1',
25 '-txospenderindex=1',
26 ]
27
28 class InitTest(BitcoinTestFramework):
29 """
30 Ensure that initialization can be interrupted at a number of points and not impair
31 subsequent starts.
32 """
33
34 def set_test_params(self):
35 self.setup_clean_chain = True
36 self.num_nodes = 2
37 self.uses_wallet = None
38
39 def check_clean_start(self, node, extra_args):
40 """Ensure that node restarts successfully after various interrupts."""
41 node.start(extra_args)
42 node.wait_for_rpc_connection()
43 height = node.getblockcount()
44 assert_equal(200, height)
45 self.wait_until(lambda: all(i["synced"] and i["best_block_height"] == height for i in node.getindexinfo().values()))
46
47 def init_stress_test_interrupt(self):
48 """
49 - test terminating initialization after seeing a certain log line.
50 """
51 self.start_node(0)
52 node = self.nodes[0]
53 self.generate(node, 200, sync_fun=self.no_op)
54 self.stop_node(0)
55
56 def sigterm_node():
57 if platform.system() == 'Windows':
58 # Don't call Python's terminate() since it calls
59 # TerminateProcess(), which unlike SIGTERM doesn't allow
60 # bitcoind to perform any shutdown logic.
61 os.kill(node.process.pid, signal.CTRL_BREAK_EVENT)
62 else:
63 node.process.terminate()
64 assert_equal(0, node.process.wait())
65
66 reindex_log_line = b'Reindexing block file blk00000.dat'
67 lines_to_terminate_after = [
68 b'Validating signatures for all blocks',
69 b'scheduler thread start',
70 b'Starting HTTP server',
71 b'Loading P2P addresses',
72 b'Loading banlist',
73 b'Loading block index',
74 b'Checking all blk files are present',
75 b'Loaded best chain:',
76 b'init message: Verifying blocks',
77 b'init message: Starting network threads',
78 b'net thread start',
79 b'addcon thread start',
80 b'initload thread start',
81 b'txidx thread start',
82 b'blkfltbscidx thread start',
83 b'coinstatsidx thread start',
84 b'txospenderidx thread start',
85 b'msghand thread start',
86 b'net thread start',
87 b'addcon thread start',
88 ]
89 if self.is_wallet_compiled():
90 lines_to_terminate_after.append(b'Verifying wallet')
91 lines_to_terminate_after.append(reindex_log_line)
92
93 for terminate_line in lines_to_terminate_after:
94 self.log.info(f"Starting node and will terminate after line {terminate_line}")
95 with node.busy_wait_for_debug_log([terminate_line]):
96 extra_args = [*ALL_INDEX_ARGS]
97 if terminate_line == reindex_log_line:
98 extra_args += ['-reindex']
99 if platform.system() == 'Windows':
100 # CREATE_NEW_PROCESS_GROUP is required in order to be able
101 # to terminate the child without terminating the test.
102 node.start(extra_args=extra_args, creationflags=subprocess.CREATE_NEW_PROCESS_GROUP)
103 else:
104 node.start(extra_args=extra_args)
105 self.log.debug("Terminating node after terminate line was found")
106 sigterm_node()
107
108 # Prior to deleting/perturbing index files, start node with all indexes enabled.
109 # 'check_clean_start' will ensure indexes are synchronized (i.e., data exists to modify)
110 self.check_clean_start(node, ALL_INDEX_ARGS)
111 self.stop_node(0)
112
113 def init_stress_test_removals(self):
114 """
115 - test removing certain essential files to test startup error paths.
116 """
117 self.log.info("Test startup errors after removing certain essential files")
118 node = self.nodes[0]
119
120 def start_expecting_error(err_fragment, args):
121 node.assert_start_raises_init_error(
122 extra_args=args,
123 expected_msg=err_fragment,
124 match=ErrorMatch.PARTIAL_REGEX,
125 )
126
127 deletion_rounds = [
128 {
129 'filepath_glob': 'blocks/index/*.ldb',
130 'error_message': 'Error opening block database.',
131 'startup_args': [],
132 },
133 {
134 'filepath_glob': 'chainstate/*.ldb',
135 'error_message': 'Error opening coins database.',
136 'startup_args': ['-checklevel=4'],
137 },
138 {
139 'filepath_glob': 'blocks/blk*.dat',
140 'error_message': 'Error loading block database.',
141 'startup_args': ['-checkblocks=200', '-checklevel=4'],
142 },
143 {
144 'filepath_glob': 'indexes/txindex/MANIFEST*',
145 'error_message': 'LevelDB error: Corruption: CURRENT points to a non-existent file',
146 'startup_args': ['-txindex=1'],
147 },
148 {
149 'filepath_glob': 'indexes/txospenderindex/db/MANIFEST*',
150 'error_message': 'LevelDB error: Corruption: CURRENT points to a non-existent file',
151 'startup_args': ['-txospenderindex=1'],
152 },
153 # Removing these files does not result in a startup error:
154 # 'indexes/blockfilter/basic/*.dat', 'indexes/blockfilter/basic/db/*.*', 'indexes/coinstatsindex/db/*.*',
155 # 'indexes/txindex/*.log', 'indexes/txindex/CURRENT', 'indexes/txindex/LOCK'
156 ]
157
158 perturbation_rounds = [
159 {
160 'filepath_glob': 'blocks/index/*.ldb',
161 'error_message': 'Error loading block database.',
162 'startup_args': [],
163 },
164 {
165 'filepath_glob': 'chainstate/*.ldb',
166 'error_message': 'Error opening coins database.',
167 'startup_args': [],
168 },
169 {
170 'filepath_glob': 'blocks/blk*.dat',
171 'error_message': 'Corrupted block database detected.',
172 'startup_args': ['-checkblocks=200', '-checklevel=4'],
173 },
174 {
175 'filepath_glob': 'indexes/blockfilter/basic/db/*.*',
176 'error_message': 'LevelDB error: Corruption',
177 'startup_args': ['-blockfilterindex=1'],
178 },
179 {
180 'filepath_glob': 'indexes/coinstatsindex/db/*.*',
181 'error_message': 'LevelDB error: Corruption',
182 'startup_args': ['-coinstatsindex=1'],
183 },
184 {
185 'filepath_glob': 'indexes/txindex/*.log',
186 'error_message': 'LevelDB error: Corruption',
187 'startup_args': ['-txindex=1'],
188 },
189 {
190 'filepath_glob': 'indexes/txindex/CURRENT',
191 'error_message': 'LevelDB error: Corruption',
192 'startup_args': ['-txindex=1'],
193 },
194 {
195 'filepath_glob': 'indexes/txospenderindex/db/*',
196 'error_message': 'LevelDB error: Corruption',
197 'startup_args': ['-txospenderindex=1'],
198 },
199 # Perturbing these files does not result in a startup error:
200 # 'indexes/blockfilter/basic/*.dat', 'indexes/txindex/MANIFEST*', 'indexes/txindex/LOCK'
201 ]
202
203 for round_info in deletion_rounds:
204 file_patt = round_info['filepath_glob']
205 err_fragment = round_info['error_message']
206 startup_args = round_info['startup_args']
207 target_files = list(node.chain_path.glob(file_patt))
208 assert target_files, f"Failed to find expected files: {file_patt}"
209
210 for target_file in target_files:
211 self.log.info(f"Deleting file to ensure failure {target_file}")
212 bak_path = str(target_file) + ".bak"
213 target_file.rename(bak_path)
214
215 start_expecting_error(err_fragment, startup_args)
216
217 for target_file in target_files:
218 bak_path = str(target_file) + ".bak"
219 self.log.debug(f"Restoring file from {bak_path} and restarting")
220 Path(bak_path).rename(target_file)
221
222 self.check_clean_start(node, ALL_INDEX_ARGS)
223 self.stop_node(0)
224
225 self.log.info("Test startup errors after perturbing certain essential files")
226 dirs = ["blocks", "chainstate", "indexes"]
227 for round_info in perturbation_rounds:
228 file_patt = round_info['filepath_glob']
229 err_fragment = round_info['error_message']
230 startup_args = round_info['startup_args']
231
232 for dir in dirs:
233 shutil.copytree(node.chain_path / dir, node.chain_path / f"{dir}_bak")
234 target_files = list(node.chain_path.glob(file_patt))
235 assert target_files, f"Failed to find expected files: {file_patt}"
236
237 for target_file in target_files:
238 self.log.info(f"Perturbing file to ensure failure {target_file}")
239 with open(target_file, "r+b") as tf:
240 # Since the genesis block is not checked by -checkblocks, the
241 # perturbation window must be chosen such that a higher block
242 # in blk*.dat is affected.
243 tf.seek(150)
244 tf.write(b"1" * 200)
245
246 start_expecting_error(err_fragment, startup_args)
247
248 for dir in dirs:
249 self.cleanup_folder(node.chain_path / dir)
250 shutil.move(node.chain_path / f"{dir}_bak", node.chain_path / dir)
251
252 def init_pid_test(self):
253 BITCOIN_PID_FILENAME_CUSTOM = "my_fancy_bitcoin_pid_file.foobar"
254
255 self.log.info("Test specifying custom pid file via -pid command line option")
256 custom_pidfile_relative = BITCOIN_PID_FILENAME_CUSTOM
257 self.log.info(f"-> path relative to datadir ({custom_pidfile_relative})")
258 self.restart_node(0, [f"-pid={custom_pidfile_relative}"])
259 datadir = self.nodes[0].chain_path
260 assert not (datadir / BITCOIN_PID_FILENAME_DEFAULT).exists()
261 assert (datadir / custom_pidfile_relative).exists()
262 self.stop_node(0)
263 assert not (datadir / custom_pidfile_relative).exists()
264
265 custom_pidfile_absolute = Path(self.options.tmpdir) / BITCOIN_PID_FILENAME_CUSTOM
266 self.log.info(f"-> absolute path ({custom_pidfile_absolute})")
267 self.restart_node(0, [f"-pid={custom_pidfile_absolute}"])
268 assert not (datadir / BITCOIN_PID_FILENAME_DEFAULT).exists()
269 assert custom_pidfile_absolute.exists()
270 self.stop_node(0)
271 assert not custom_pidfile_absolute.exists()
272
273 def break_wait_test(self):
274 """Test what happens when a break signal is sent during a
275 waitforblockheight RPC call with a long timeout. Ctrl-Break is sent on
276 Windows and SIGTERM is sent on other platforms, to trigger the same node
277 shutdown sequence that would happen if Ctrl-C were pressed in a
278 terminal. (This can be different than the node shutdown sequence that
279 happens when the stop RPC is sent.)
280
281 The waitforblockheight call should be interrupted and return right away,
282 and not time out."""
283
284 self.log.info("Testing waitforblockheight RPC call followed by break signal")
285 node = self.nodes[0]
286
287 if platform.system() == 'Windows':
288 # CREATE_NEW_PROCESS_GROUP prevents python test from exiting
289 # with STATUS_CONTROL_C_EXIT (-1073741510) when break is sent.
290 self.start_node(node.index, creationflags=subprocess.CREATE_NEW_PROCESS_GROUP)
291 else:
292 self.start_node(node.index)
293
294 current_height = node.getblock(node.getbestblockhash())['height']
295
296 with ThreadPoolExecutor(max_workers=1) as ex:
297 # Call waitforblockheight with wait timeout longer than RPC timeout,
298 # so it is possible to distinguish whether it times out or returns
299 # early. If it times out it will throw an exception, and if it
300 # returns early it will return the current block height.
301 self.log.debug(f"Calling waitforblockheight with {self.rpc_timeout} sec RPC timeout")
302 fut = ex.submit(node.waitforblockheight, height=current_height+1, timeout=self.rpc_timeout*1000*2)
303
304 self.wait_until(lambda: any(c["method"] == "waitforblockheight" for c in node.cli.getrpcinfo()["active_commands"]))
305
306 self.log.debug(f"Sending break signal to pid {node.process.pid}")
307 if platform.system() == 'Windows':
308 # Note: CTRL_C_EVENT should not be sent here because unlike
309 # CTRL_BREAK_EVENT it can not be targeted at a specific process
310 # group and may behave unpredictably.
311 node.process.send_signal(signal.CTRL_BREAK_EVENT)
312 else:
313 # Note: signal.SIGINT would work here as well
314 node.process.send_signal(signal.SIGTERM)
315 node.process.wait()
316
317 result = fut.result()
318 self.log.debug(f"waitforblockheight returned {result!r}")
319 assert_equal(result["height"], current_height)
320 node.wait_until_stopped()
321
322 def init_empty_test(self):
323 self.log.info("Test that stopping and restarting a node that has done nothing is not causing a failure")
324 options = [
325 [],
326 ALL_INDEX_ARGS,
327 ]
328 for option in options:
329 self.restart_node(1, option)
330
331 def restart_node_with_fd_limit(self, limit):
332 """Restart node 1 with a given soft RLIMIT_NOFILE. Skips if the limit cannot be set."""
333 import resource
334 soft, hard = resource.getrlimit(resource.RLIMIT_NOFILE)
335 try:
336 resource.setrlimit(resource.RLIMIT_NOFILE, (limit, hard))
337 except (ValueError, OSError):
338 self.log.info(f"Skipping rlimit test: cannot set soft limit (hard={hard})")
339 return
340 try:
341 self.restart_node(1)
342 self.log.debug(f"Node started successfully with RLIM_INFINITY limit (soft={limit})")
343 finally:
344 resource.setrlimit(resource.RLIMIT_NOFILE, (soft, hard))
345 self.log.debug(f"Restored previous RLIMIT_NOFILE limits (soft={soft}, hard={hard})")
346
347 def init_rlimit_test(self):
348 """Test that bitcoind starts correctly when the soft RLIMIT_NOFILE limit is RLIM_INFINITY."""
349 if self.RLIM_INFINITY is None:
350 self.log.info("Skipping: resource module not available")
351 return
352
353 self.log.info("Testing node startup with RLIM_INFINITY fd limit")
354 self.restart_node_with_fd_limit(self.RLIM_INFINITY)
355
356 def init_rlimit_large_test(self):
357 """Test that bitcoind starts correctly when the soft RLIMIT_NOFILE limit is above INT_MAX."""
358 if self.RLIM_INFINITY is None:
359 self.log.info("Skipping: resource module not available")
360 return
361
362 self.log.info("Testing node startup with fd limit above INT_MAX")
363 self.restart_node_with_fd_limit(1 << 31)
364
365 def run_test(self):
366 self.init_pid_test()
367 self.init_stress_test_interrupt()
368 self.init_stress_test_removals()
369 self.break_wait_test()
370 self.init_empty_test()
371 self.init_rlimit_test()
372 self.init_rlimit_large_test()
373
374
375 if __name__ == '__main__':
376 InitTest(__file__).main()
377