merge bitcoin#23737: make feature_init more robust

test/functional/feature_init.py

@@ -44,14 +44,9 @@ 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."""
-            # 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())
@@ -71,56 +66,33 @@ class InitStressTest(BitcoinTestFramework):
             'net thread start',
             'addcon thread start',
             'loadblk thread start',
-            # TODO: reenable - see above TODO
+            'txindex thread start',
-            # 'txindex thread start',
+            'msghand 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(
+            node.start(extra_args=['-txindex=1'])
-                # 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
+            num_total_logs = node.wait_for_debug_log([terminate_line], ignore_case=True)
-            start = time.time()
+            self.log.debug(f"Terminating node after {num_total_logs} log lines seen")
-            num_lines = 0
+            sigterm_node()
-
-            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}')")
 
         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)
+            num_logs = len(Path(node.debug_log_path).read_text().splitlines())
-            self.log.debug(f"Starting node and will exit after {terminate_after} lines")
+            additional_lines = random.randint(1, num_total_logs)
-            node.start(
+            self.log.debug(f"Starting node and will exit after {additional_lines} lines")
-                # TODO: add -txindex=1 to fully test index initiatlization.
+            node.start(extra_args=['-txindex=1'])
-                # extra_args=['-txindex=1'],
-            )
             logfile = open(node.debug_log_path, 'r', encoding='utf8')
 
             MAX_SECS_TO_WAIT = 10
@@ -132,7 +104,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
@@ -152,11 +125,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}")
+            for target_file in target_files:
-            bak_path = str(target_file) + ".bak"
+                self.log.info(f"Tweaking file to ensure failure {target_file}")
-            target_file.rename(bak_path)
+                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.
@@ -170,14 +144,16 @@ 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,
             )
 
-            self.log.info(f"Restoring file from {bak_path} and restarting")
+            for target_file in target_files:
-            Path(bak_path).rename(target_file)
+                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)
 

test/functional/test_framework/test_node.py

@@ -409,14 +409,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:
+        prev_size = self.debug_log_bytes()
-            dl.seek(0, 2)
-            prev_size = dl.tell()
 
         yield
 
@@ -439,6 +442,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):
         """