Merge bitcoin#24192: test: Fix feature_init intermittent issues

fa7b075 test: Fix feature_init intermittent issues (MarcoFalke)
fa4595d test: Remove random line number feature from feature_init.py (MarcoFalke)

Pull request description:

  The test doesn't work currently because the log might be finalized before `wait_for_debug_log` is started, in which case it will assume the log is empty and fail to detect any line.

  Fix this by calling `wait_for_debug_log` first. Fixes bitcoin#24060.

  Also, remove the "random line number" part of the test, because 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.

ACKs for top commit:
  jamesob:
    ACK bitcoin@fa7b075
  mzumsande:
    Code Review ACK fa7b075

Tree-SHA512: f107a04926270a1d9ac8f53b6e5254566d1827ba7d27fd74f9ce909319f8794f8bd46da9c42256bf41b6df26c0bad8b9a0d54e4e148695189af09f31e3948330

Author: MarcoFalke

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 @@ def set_test_params(self):
     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,46 +73,14 @@ def check_clean_start():
 
         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()
         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 = {

test/functional/test_framework/test_node.py

@@ -422,7 +422,8 @@ def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
             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 @@ def wait_for_debug_log(self, expected_msgs, timeout=10, ignore_case=False) -> in
         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 @@ def wait_for_debug_log(self, expected_msgs, timeout=10, ignore_case=False) -> in
                     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 @@ def wait_for_debug_log(self, expected_msgs, timeout=10, ignore_case=False) -> in
         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):