From a2fb62b632d39e468f59e7e0b6890f82d0f5eebb Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Fri, 10 Dec 2021 14:23:18 -0500 Subject: [PATCH 1/5] test: introduce TestNode.debug_log_bytes --- test/functional/test_framework/test_node.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index ca6e341be83..49d885f7933 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -389,14 +389,17 @@ class TestNode(): def debug_log_path(self) -> Path: return self.chain_path / 'debug.log' + def debug_log_bytes(self) -> int: + with open(self.debug_log_path, encoding='utf-8') as dl: + dl.seek(0, 2) + return dl.tell() + @contextlib.contextmanager def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2): if unexpected_msgs is None: unexpected_msgs = [] time_end = time.time() + timeout * self.timeout_factor - with open(self.debug_log_path, encoding='utf-8') as dl: - dl.seek(0, 2) - prev_size = dl.tell() + prev_size = self.debug_log_bytes() yield From a8ffbc01db85d918b8d1406b178b3c6f09123cf1 Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Fri, 10 Dec 2021 14:26:04 -0500 Subject: [PATCH 2/5] test: add TestNode.wait_for_debug_log --- test/functional/test_framework/test_node.py | 36 +++++++++++++++++++++ 1 file changed, 36 insertions(+) diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 49d885f7933..0b9154a0305 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -422,6 +422,42 @@ class TestNode(): time.sleep(0.05) self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log)) + def wait_for_debug_log(self, expected_msgs, timeout=10, ignore_case=False) -> int: + """ + Block until we see a particular debug log message fragment or until we exceed the timeout. + Return: + the number of log lines we encountered when matching + """ + time_end = time.time() + timeout * self.timeout_factor + prev_size = self.debug_log_bytes() + re_flags = re.MULTILINE | (re.IGNORECASE if ignore_case else 0) + + while True: + found = True + with open(self.debug_log_path, encoding='utf-8') as dl: + dl.seek(prev_size) + log = dl.read() + + for expected_msg in expected_msgs: + if re.search(re.escape(expected_msg), log, flags=re_flags) is None: + found = False + + if found: + num_logs = len(log.splitlines()) + return num_logs + + if time.time() >= time_end: + print_log = " - " + "\n - ".join(log.splitlines()) + break + + # No sleep here because we want to detect the message fragment as fast as + # possible. + + self._raise_assertion_error( + 'Expected messages "{}" does not partially match log:\n\n{}\n\n'.format( + str(expected_msgs), print_log)) + return -1 # useless return to satisfy linter + @contextlib.contextmanager def profile_with_perf(self, profile_name: str): """ From 24fcf6e435ee53191b1404a11b0689bcd647c9e2 Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Fri, 10 Dec 2021 14:31:01 -0500 Subject: [PATCH 3/5] test: feature_init: tweak all .ldb files of a certain type This part of the test sporadically fails on CI infrastructure. Instead of perturbing a single .ldb file of each type, move all .ldb files of a given type to ensure a bad startup. --- test/functional/feature_init.py | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/test/functional/feature_init.py b/test/functional/feature_init.py index 40468c66e28..a82238f7cf1 100755 --- a/test/functional/feature_init.py +++ b/test/functional/feature_init.py @@ -152,11 +152,12 @@ class InitStressTest(BitcoinTestFramework): } for file_patt, err_fragment in files_to_disturb.items(): - target_file = list(node.chain_path.glob(file_patt))[0] + target_files = list(node.chain_path.glob(file_patt)) - self.log.info(f"Tweaking file to ensure failure {target_file}") - bak_path = str(target_file) + ".bak" - target_file.rename(bak_path) + for target_file in target_files: + self.log.info(f"Tweaking file to ensure failure {target_file}") + bak_path = str(target_file) + ".bak" + target_file.rename(bak_path) # TODO: at some point, we should test perturbing the files instead of removing # them, e.g. @@ -176,8 +177,11 @@ class InitStressTest(BitcoinTestFramework): match=ErrorMatch.PARTIAL_REGEX, ) - self.log.info(f"Restoring file from {bak_path} and restarting") - Path(bak_path).rename(target_file) + for target_file in target_files: + bak_path = str(target_file) + ".bak" + self.log.debug(f"Restoring file from {bak_path} and restarting") + Path(bak_path).rename(target_file) + check_clean_start() self.stop_node(0) From 93db6d8422345cc10db333d56ea9bcceefcf58b6 Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Fri, 10 Dec 2021 14:32:24 -0500 Subject: [PATCH 4/5] test: feature_init: retain debug.log and improve detection This test sporadically fails due to the Python test missing log lines for reasons that are poorly understood. The problem is made worse by the fact that this test does not retain the log files from iteration to iteration. Change the test to do logline detection in a more robust manner (by using `re.search` on the whole log content) in a way that is comparable to the existing `assert_debug_log` utility, and retain all debug.log content from case to case. --- test/functional/feature_init.py | 37 ++++++++------------------------- 1 file changed, 9 insertions(+), 28 deletions(-) diff --git a/test/functional/feature_init.py b/test/functional/feature_init.py index a82238f7cf1..04a851bd85c 100755 --- a/test/functional/feature_init.py +++ b/test/functional/feature_init.py @@ -44,8 +44,6 @@ class InitStressTest(BitcoinTestFramework): def sigterm_node(): node.process.terminate() node.process.wait() - node.debug_log_path.unlink() - node.debug_log_path.touch() def check_clean_start(): """Ensure that node restarts successfully after various interrupts.""" @@ -71,7 +69,7 @@ class InitStressTest(BitcoinTestFramework): 'net thread start', 'addcon thread start', 'loadblk thread start', - # TODO: reenable - see above TODO + # TODO: re-enable - see above TODO # 'txindex thread start', 'msghand thread start' ] @@ -84,39 +82,21 @@ class InitStressTest(BitcoinTestFramework): # TODO: add -txindex=1 to fully test index initiatlization. # extra_args=['-txindex=1'], ) - logfile = open(node.debug_log_path, 'r', encoding='utf8') - - MAX_SECS_TO_WAIT = 30 - start = time.time() - num_lines = 0 - while True: - line = logfile.readline() - if line: - num_lines += 1 - - if line and terminate_line.lower() in line.lower(): - self.log.debug(f"Terminating node after {num_lines} log lines seen") - sigterm_node() - break - - if (time.time() - start) > MAX_SECS_TO_WAIT: - raise AssertionError( - f"missed line {terminate_line}; terminating now after {num_lines} lines") - - if node.process.poll() is not None: - raise AssertionError(f"node failed to start (line: '{terminate_line}')") + num_total_logs = node.wait_for_debug_log([terminate_line], ignore_case=True) + self.log.debug(f"Terminating node after {num_total_logs} log lines seen") + sigterm_node() check_clean_start() - num_total_logs = len(node.debug_log_path.read_text().splitlines()) self.stop_node(0) self.log.info( f"Terminate at some random point in the init process (max logs: {num_total_logs})") for _ in range(40): - terminate_after = random.randint(1, num_total_logs) - self.log.debug(f"Starting node and will exit after {terminate_after} lines") + num_logs = len(Path(node.debug_log_path).read_text().splitlines()) + additional_lines = random.randint(1, num_total_logs) + self.log.debug(f"Starting node and will exit after {additional_lines} lines") node.start( # TODO: add -txindex=1 to fully test index initiatlization. # extra_args=['-txindex=1'], @@ -132,7 +112,8 @@ class InitStressTest(BitcoinTestFramework): if line: num_lines += 1 - if num_lines >= terminate_after or (time.time() - start) > MAX_SECS_TO_WAIT: + if num_lines >= (num_logs + additional_lines) or \ + (time.time() - start) > MAX_SECS_TO_WAIT: self.log.debug(f"Terminating node after {num_lines} log lines seen") sigterm_node() break From 8904f17ea715f3d28f18c1b8ce46a39ff2076144 Mon Sep 17 00:00:00 2001 From: James O'Beirne Date: Mon, 13 Dec 2021 08:18:36 -0500 Subject: [PATCH 5/5] test: enable txindex in feature_init Now that #23365 is merged. --- test/functional/feature_init.py | 23 +++++++---------------- 1 file changed, 7 insertions(+), 16 deletions(-) diff --git a/test/functional/feature_init.py b/test/functional/feature_init.py index 04a851bd85c..16815c1afcd 100755 --- a/test/functional/feature_init.py +++ b/test/functional/feature_init.py @@ -47,9 +47,6 @@ class InitStressTest(BitcoinTestFramework): def check_clean_start(): """Ensure that node restarts successfully after various interrupts.""" - # TODO: add -txindex=1 to fully test index initiatlization. - # See https://github.com/bitcoin/bitcoin/pull/23289#discussion_r735159180 for - # a discussion of the related bug. node.start() node.wait_for_rpc_connection() assert_equal(200, node.getblockcount()) @@ -69,19 +66,17 @@ class InitStressTest(BitcoinTestFramework): 'net thread start', 'addcon thread start', 'loadblk thread start', - # TODO: re-enable - see above TODO - # 'txindex thread start', - 'msghand thread start' + 'txindex thread start', + 'msghand thread start', + 'net thread start', + 'addcon thread start', ] if self.is_wallet_compiled(): lines_to_terminate_after.append('Verifying wallet') for terminate_line in lines_to_terminate_after: self.log.info(f"Starting node and will exit after line '{terminate_line}'") - node.start( - # TODO: add -txindex=1 to fully test index initiatlization. - # extra_args=['-txindex=1'], - ) + node.start(extra_args=['-txindex=1']) num_total_logs = node.wait_for_debug_log([terminate_line], ignore_case=True) self.log.debug(f"Terminating node after {num_total_logs} log lines seen") @@ -97,10 +92,7 @@ class InitStressTest(BitcoinTestFramework): num_logs = len(Path(node.debug_log_path).read_text().splitlines()) additional_lines = random.randint(1, num_total_logs) self.log.debug(f"Starting node and will exit after {additional_lines} lines") - node.start( - # TODO: add -txindex=1 to fully test index initiatlization. - # extra_args=['-txindex=1'], - ) + node.start(extra_args=['-txindex=1']) logfile = open(node.debug_log_path, 'r', encoding='utf8') MAX_SECS_TO_WAIT = 10 @@ -152,8 +144,7 @@ class InitStressTest(BitcoinTestFramework): # investigate doing this later. node.assert_start_raises_init_error( - # TODO: add -txindex=1 to fully test index initiatlization. - # extra_args=['-txindex=1'], + extra_args=['-txindex=1'], expected_msg=err_fragment, match=ErrorMatch.PARTIAL_REGEX, )