From fa4595deb334f14dac9ba481d786a823e0f0fde1 Mon Sep 17 00:00:00 2001 From: MarcoFalke Date: Mon, 31 Jan 2022 10:19:32 +0100 Subject: [PATCH 1/2] test: Remove random line number feature from feature_init.py This is needed for the next commit. Also, it doesn't really test anything novel. wait_for_debug_log is inherently racy, so will randomly terminate at the exact point or later. So the randomization is already sufficiently covered by the existing test. --- test/functional/feature_init.py | 31 ------------------------------- 1 file changed, 31 deletions(-) diff --git a/test/functional/feature_init.py b/test/functional/feature_init.py index 4b56b0c26b9..427f9f10efd 100755 --- a/test/functional/feature_init.py +++ b/test/functional/feature_init.py @@ -85,37 +85,6 @@ class InitStressTest(BitcoinTestFramework): check_clean_start() 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): - 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(extra_args=['-txindex=1']) - logfile = open(node.debug_log_path, 'rb') - - MAX_SECS_TO_WAIT = 10 - start = time.time() - num_lines = 0 - - while True: - line = logfile.readline() - if line: - num_lines += 1 - - 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 - - if node.process.poll() is not None: - raise AssertionError("node failed to start") - - check_clean_start() - self.stop_node(0) - self.log.info("Test startup errors after removing certain essential files") files_to_disturb = { From fa7b07571f24b6def6effdd4cc1b96c7507bf959 Mon Sep 17 00:00:00 2001 From: MarcoFalke Date: Fri, 28 Jan 2022 13:40:15 +0100 Subject: [PATCH 2/2] test: Fix feature_init intermittent issues --- test/functional/feature_init.py | 10 +++------- test/functional/test_framework/test_node.py | 9 +++++---- 2 files changed, 8 insertions(+), 11 deletions(-) diff --git a/test/functional/feature_init.py b/test/functional/feature_init.py index 427f9f10efd..dbd71a8b2df 100755 --- a/test/functional/feature_init.py +++ b/test/functional/feature_init.py @@ -3,8 +3,6 @@ # Distributed under the MIT software license, see the accompanying # file COPYING or http://www.opensource.org/licenses/mit-license.php. """Stress tests related to node initialization.""" -import random -import time import os from pathlib import Path @@ -26,7 +24,6 @@ class InitStressTest(BitcoinTestFramework): def run_test(self): """ - test terminating initialization after seeing a certain log line. - - test terminating init after seeing a random number of log lines. - test removing certain essential files to test startup error paths. """ # TODO: skip Windows for now since it isn't clear how to SIGTERM. @@ -76,10 +73,9 @@ class InitStressTest(BitcoinTestFramework): for terminate_line in lines_to_terminate_after: self.log.info(f"Starting node and will exit after line '{terminate_line}'") - 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") + with node.wait_for_debug_log([terminate_line], ignore_case=True): + node.start(extra_args=['-txindex=1']) + self.log.debug("Terminating node after terminate line was found") sigterm_node() check_clean_start() diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 0b9154a0305..289e83579b5 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -422,7 +422,8 @@ 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: + @contextlib.contextmanager + def wait_for_debug_log(self, expected_msgs, timeout=60, ignore_case=False): """ Block until we see a particular debug log message fragment or until we exceed the timeout. Return: @@ -432,6 +433,8 @@ class TestNode(): prev_size = self.debug_log_bytes() re_flags = re.MULTILINE | (re.IGNORECASE if ignore_case else 0) + yield + while True: found = True with open(self.debug_log_path, encoding='utf-8') as dl: @@ -443,8 +446,7 @@ class TestNode(): found = False if found: - num_logs = len(log.splitlines()) - return num_logs + return if time.time() >= time_end: print_log = " - " + "\n - ".join(log.splitlines()) @@ -456,7 +458,6 @@ class TestNode(): 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):