tests(integ): add more debug logging (#5363)

Author: lrstewart

tests/integrationv2/fixtures.py

@@ -66,6 +66,7 @@ def _fn(
         p = ManagedProcess(
             cmd_line,
             provider.set_provider_ready,
+            name=provider.get_name(cmd_line),
             wait_for_marker=provider.ready_to_test_marker,
             send_marker_list=provider.ready_to_send_input_marker,
             close_marker=close_marker,

tests/integrationv2/processes.py

@@ -116,6 +116,14 @@ def _communicate(
         send_with_newline=False,
         timeout=None,
     ):
+        print(
+            f"{self.name}: Handling process IO: \n"
+            f"    wait_for_marker: {self.wait_for_marker} \n"
+            f"    send_markers: {send_marker_list} \n"
+            f"    close_marker: {close_marker} \n"
+            f"    kill_marker: {kill_marker}"
+        )
+
         """
         This method will read and write data to a subprocess in a non-blocking manner.
         The code is heavily based on Popen.communicate. There are a couple differences:
@@ -304,7 +312,7 @@ def _communicate(
                         if close_marker is None or (
                             close_marker and close_marker in data_str
                         ):
-                            print(f"{self.name} Found close marker: closing stdin")
+                            print(f"{self.name}: Found close marker: closing stdin")
                             input_data_sent = None
                             self.proc.stdin.close()
 
@@ -358,6 +366,7 @@ def __init__(
         self,
         cmd_line,
         provider_set_ready_condition,
+        name,
         wait_for_marker=None,
         send_marker_list=None,
         close_marker=None,
@@ -380,6 +389,8 @@ def __init__(
         # Command line to execute in the subprocess
         self.cmd_line = list(map(str, cmd_line))
 
+        self.name = name
+
         # Total time to wait until killing the subprocess
         self.timeout = timeout
 
@@ -426,7 +437,7 @@ def run(self):
                 self.results = Results(None, None, None, ex, self.expect_stderr)
                 raise ex
 
-            communicator = _processCommunicator(proc, self.cmd_line[0])
+            communicator = _processCommunicator(proc, self.name)
 
             if self.ready_to_test is not None:
                 # Some processes won't be ready until they have emitted some string in stdout.
@@ -454,10 +465,12 @@ def run(self):
                     expect_nonzero_exit=self.kill_marker is not None,
                 )
             except subprocess.TimeoutExpired as ex:
+                print(f"{communicator.name}: TIMEOUT. Killing process.")
                 proc.kill()
                 wrapped_ex = TimeoutException(ex)
 
                 # Read any remaining output
+                print(f"{communicator.name}: TIMEOUT. Reading remaining output.")
                 proc_results = communicator.communicate()
                 self.results = Results(
                     proc_results[0],

tests/integrationv2/providers.py

@@ -106,6 +106,10 @@ def set_provider_ready(self):
     def supports_certificate(cls, cert: Cert):
         return True
 
+    @classmethod
+    def get_name(cls, cmd_line):
+        return cmd_line[0]
+
 
 class Tcpdump(Provider):
     """
@@ -595,6 +599,10 @@ def setup_server(self):
 
         return cmd_line
 
+    @classmethod
+    def get_name(cls, cmd_line):
+        return cmd_line[1]
+
 
 class SSLv3Provider(OpenSSL):
     def __init__(self, options: ProviderOptions):