|
| 1 | +#!/usr/bin/env python3 |
| 2 | +# Copyright (c) 2021 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 | +"""Stress tests related to node initialization.""" |
| 6 | +import random |
| 7 | +import time |
| 8 | +import os |
| 9 | +from pathlib import Path |
| 10 | + |
| 11 | +from test_framework.test_framework import BitcoinTestFramework, SkipTest |
| 12 | +from test_framework.test_node import ErrorMatch |
| 13 | +from test_framework.util import assert_equal |
| 14 | + |
| 15 | + |
| 16 | +class InitStressTest(BitcoinTestFramework): |
| 17 | + """ |
| 18 | + Ensure that initialization can be interrupted at a number of points and not impair |
| 19 | + subsequent starts. |
| 20 | + """ |
| 21 | + |
| 22 | + def set_test_params(self): |
| 23 | + self.setup_clean_chain = False |
| 24 | + self.num_nodes = 1 |
| 25 | + |
| 26 | + def run_test(self): |
| 27 | + """ |
| 28 | + - test terminating initialization after seeing a certain log line. |
| 29 | + - test terminating init after seeing a random number of log lines. |
| 30 | + - test removing certain essential files to test startup error paths. |
| 31 | + """ |
| 32 | + # TODO: skip Windows for now since it isn't clear how to SIGTERM. |
| 33 | + # |
| 34 | + # Windows doesn't support `process.terminate()`. |
| 35 | + # and other approaches (like below) don't work: |
| 36 | + # |
| 37 | + # os.kill(node.process.pid, signal.CTRL_C_EVENT) |
| 38 | + if os.name == 'nt': |
| 39 | + raise SkipTest("can't SIGTERM on Windows") |
| 40 | + |
| 41 | + self.stop_node(0) |
| 42 | + node = self.nodes[0] |
| 43 | + |
| 44 | + def sigterm_node(): |
| 45 | + node.process.terminate() |
| 46 | + node.process.wait() |
| 47 | + node.debug_log_path.unlink() |
| 48 | + node.debug_log_path.touch() |
| 49 | + |
| 50 | + def check_clean_start(): |
| 51 | + """Ensure that node restarts successfully after various interrupts.""" |
| 52 | + # TODO: add -txindex=1 to fully test index initiatlization. |
| 53 | + # See https://github.com/bitcoin/bitcoin/pull/23289#discussion_r735159180 for |
| 54 | + # a discussion of the related bug. |
| 55 | + node.start() |
| 56 | + node.wait_for_rpc_connection() |
| 57 | + assert_equal(200, node.getblockcount()) |
| 58 | + |
| 59 | + lines_to_terminate_after = [ |
| 60 | + 'scheduler thread start', |
| 61 | + 'Loading P2P addresses', |
| 62 | + 'Loading banlist', |
| 63 | + 'Loading block index', |
| 64 | + 'Switching active chainstate', |
| 65 | + 'Loaded best chain:', |
| 66 | + 'init message: Verifying blocks', |
| 67 | + 'loadblk thread start', |
| 68 | + # TODO: reenable - see above TODO |
| 69 | + # 'txindex thread start', |
| 70 | + 'net thread start', |
| 71 | + 'addcon thread start', |
| 72 | + 'msghand thread start', |
| 73 | + ] |
| 74 | + if self.is_wallet_compiled(): |
| 75 | + lines_to_terminate_after.append('Verifying wallet') |
| 76 | + |
| 77 | + for terminate_line in lines_to_terminate_after: |
| 78 | + self.log.info(f"Starting node and will exit after line '{terminate_line}'") |
| 79 | + node.start( |
| 80 | + # TODO: add -txindex=1 to fully test index initiatlization. |
| 81 | + # extra_args=['-txindex=1'], |
| 82 | + ) |
| 83 | + logfile = open(node.debug_log_path, 'r', encoding='utf8') |
| 84 | + |
| 85 | + MAX_SECS_TO_WAIT = 30 |
| 86 | + start = time.time() |
| 87 | + num_lines = 0 |
| 88 | + |
| 89 | + while True: |
| 90 | + line = logfile.readline() |
| 91 | + if line: |
| 92 | + num_lines += 1 |
| 93 | + |
| 94 | + if line and terminate_line.lower() in line.lower(): |
| 95 | + self.log.debug(f"Terminating node after {num_lines} log lines seen") |
| 96 | + sigterm_node() |
| 97 | + break |
| 98 | + |
| 99 | + if (time.time() - start) > MAX_SECS_TO_WAIT: |
| 100 | + raise AssertionError( |
| 101 | + f"missed line {terminate_line}; terminating now after {num_lines} lines") |
| 102 | + |
| 103 | + if node.process.poll() is not None: |
| 104 | + raise AssertionError(f"node failed to start (line: '{terminate_line}')") |
| 105 | + |
| 106 | + check_clean_start() |
| 107 | + num_total_logs = len(node.debug_log_path.read_text().splitlines()) |
| 108 | + self.stop_node(0) |
| 109 | + |
| 110 | + self.log.info( |
| 111 | + f"Terminate at some random point in the init process (max logs: {num_total_logs})") |
| 112 | + |
| 113 | + for _ in range(40): |
| 114 | + terminate_after = random.randint(1, num_total_logs) |
| 115 | + self.log.debug(f"Starting node and will exit after {terminate_after} lines") |
| 116 | + node.start( |
| 117 | + # TODO: add -txindex=1 to fully test index initiatlization. |
| 118 | + # extra_args=['-txindex=1'], |
| 119 | + ) |
| 120 | + logfile = open(node.debug_log_path, 'r', encoding='utf8') |
| 121 | + |
| 122 | + MAX_SECS_TO_WAIT = 10 |
| 123 | + start = time.time() |
| 124 | + num_lines = 0 |
| 125 | + |
| 126 | + while True: |
| 127 | + line = logfile.readline() |
| 128 | + if line: |
| 129 | + num_lines += 1 |
| 130 | + |
| 131 | + if num_lines >= terminate_after or (time.time() - start) > MAX_SECS_TO_WAIT: |
| 132 | + self.log.debug(f"Terminating node after {num_lines} log lines seen") |
| 133 | + sigterm_node() |
| 134 | + break |
| 135 | + |
| 136 | + if node.process.poll() is not None: |
| 137 | + raise AssertionError("node failed to start") |
| 138 | + |
| 139 | + check_clean_start() |
| 140 | + self.stop_node(0) |
| 141 | + |
| 142 | + self.log.info("Test startup errors after removing certain essential files") |
| 143 | + |
| 144 | + files_to_disturb = { |
| 145 | + 'blocks/index/*.ldb': 'Error opening block database.', |
| 146 | + 'chainstate/*.ldb': 'Error opening block database.', |
| 147 | + 'blocks/blk*.dat': 'Error loading block database.', |
| 148 | + } |
| 149 | + |
| 150 | + for file_patt, err_fragment in files_to_disturb.items(): |
| 151 | + target_file = list(node.chain_path.glob(file_patt))[0] |
| 152 | + |
| 153 | + self.log.info(f"Tweaking file to ensure failure {target_file}") |
| 154 | + bak_path = str(target_file) + ".bak" |
| 155 | + target_file.rename(bak_path) |
| 156 | + |
| 157 | + # TODO: at some point, we should test perturbing the files instead of removing |
| 158 | + # them, e.g. |
| 159 | + # |
| 160 | + # contents = target_file.read_bytes() |
| 161 | + # tweaked_contents = bytearray(contents) |
| 162 | + # tweaked_contents[50:250] = b'1' * 200 |
| 163 | + # target_file.write_bytes(bytes(tweaked_contents)) |
| 164 | + # |
| 165 | + # At the moment I can't get this to work (bitcoind loads successfully?) so |
| 166 | + # investigate doing this later. |
| 167 | + |
| 168 | + node.assert_start_raises_init_error( |
| 169 | + # TODO: add -txindex=1 to fully test index initiatlization. |
| 170 | + # extra_args=['-txindex=1'], |
| 171 | + expected_msg=err_fragment, |
| 172 | + match=ErrorMatch.PARTIAL_REGEX, |
| 173 | + ) |
| 174 | + |
| 175 | + self.log.info(f"Restoring file from {bak_path} and restarting") |
| 176 | + Path(bak_path).rename(target_file) |
| 177 | + check_clean_start() |
| 178 | + self.stop_node(0) |
| 179 | + |
| 180 | + |
| 181 | +if __name__ == '__main__': |
| 182 | + InitStressTest().main() |
0 commit comments