Merge pull request #283 from Venkat-Kunaparaju/debug-enhance

Add debug logging for test failures and suppress expected block errors

Author: wizhaoredhat

task.py

@@ -996,6 +996,14 @@ def aggregate_output(self, tft_result_builder: tftbase.TftResultBuilder) -> None
 
         if not result.success:
             logger.warn(f"Result of {type(self).__name__} failed: {result.eval_msg}")
+            logger.debug(
+                f"Failure details: pod={self.pod_name}, "
+                f"port={getattr(self, 'port', 'N/A')}, "
+                f"node={self.node_name}, "
+                f"test_type={getattr(self, 'test_type', 'N/A')}, "
+                f"connection_mode="
+                f"{getattr(self, 'connection_mode', 'N/A')}"
+            )
         else:
             self._aggregate_output_log_success(result)
 
@@ -1187,6 +1195,11 @@ def confirm_server_alive(self) -> None:
             )
         if not r:
             logger.error(f"Failed to start server {self.pod_name}: {r.err}")
+            logger.debug(
+                f"Server startup failure details: pod={self.pod_name}, "
+                f"port={self.port}, node={self.node_name}, "
+                f"connection_mode={self.connection_mode.name}"
+            )
             raise RuntimeError(f"Failed to start server {self.pod_name}: {r.err}")
 
         if not self.pre_provisioning:
@@ -1264,6 +1277,11 @@ def _wait_for_server_listening(self) -> None:
             check_port = self.external_port if is_external else self.port
             error_msg = f"Server failed to start listening on port {check_port} within {max_wait_time}s"
         logger.error(error_msg)
+        logger.debug(
+            f"Server listen timeout: pod={self.pod_name}, "
+            f"port={self.port}, node={self.node_name}, "
+            f"connection_mode={self.connection_mode.name}"
+        )
         raise RuntimeError(error_msg)
 
     @abstractmethod

testTypeHttp.py

@@ -87,6 +87,8 @@ def _check_success_podman(r: host.Result) -> bool:
                     err="",
                 )
 
+        expects_blocked = self.ts.test_case_id.info.expects_blocked
+
         def _thread_action() -> BaseOutput:
             self.ts.clmo_barrier.wait()
 
@@ -99,7 +101,7 @@ def _thread_action() -> BaseOutput:
             end_timestamp = time.monotonic() + self.get_duration() - sleep_time
 
             while True:
-                r = self.run_oc_exec(cmd)
+                r = self.run_oc_exec(cmd, may_fail=expects_blocked)
                 if not _check_success(r):
                     break
                 if time.monotonic() >= end_timestamp:
@@ -120,6 +122,17 @@ def _thread_action() -> BaseOutput:
             else:
                 msg = f'Output of "{cmd}" failed: {r.debug_msg()[:100]}'
 
+            if not success and not expects_blocked:
+                logger.debug(
+                    f"HTTP failure context: "
+                    f"client_pod={self.pod_name}, "
+                    f"server_pod={self.server.pod_name}, "
+                    f"server_port={self.server.port}, "
+                    f"node={self.node_name}, "
+                    f"exit_code={r.returncode}, "
+                    f"error={r.err.strip()!r}"
+                )
+
             # For deny tests, curl failing to connect is the expected outcome.
             test_metadata = self.ts.get_test_metadata()
             if test_metadata.expects_blocked:

testTypeIperf.py

@@ -156,9 +156,11 @@ def _create_task_operation(self) -> TaskOperation:
         if self.reverse:
             cmd += f" {IPERF_REV_OPT}"
 
+        expects_blocked = self.ts.test_case_id.info.expects_blocked
+
         def _thread_action() -> BaseOutput:
             self.ts.clmo_barrier.wait()
-            r = self.run_oc_exec(cmd)
+            r = self.run_oc_exec(cmd, may_fail=expects_blocked)
             self.ts.event_client_finished.set()
 
             success = True
@@ -168,9 +170,20 @@ def _thread_action() -> BaseOutput:
             if not r.success:
                 success = False
                 msg = f'Command "{cmd}" failed: {r.debug_msg()}'
+                if not expects_blocked:
+                    logger.debug(
+                        f"iperf3 failure context: "
+                        f"client_pod={self.pod_name}, "
+                        f"server_pod={self.server.pod_name}, "
+                        f"server_port={self.server.port}, "
+                        f"node={self.node_name}, "
+                        f"exit_code={r.returncode}, "
+                        f"error={r.err.strip()!r}"
+                    )
 
-            # Log raw output for debugging
-            logger.debug(f"iperf3 raw output: {repr(r.out)}")
+            if not expects_blocked:
+                # Log raw output for debugging
+                logger.debug(f"iperf3 raw output: {repr(r.out)}")
 
             if success:
                 try:
@@ -195,6 +208,14 @@ def _thread_action() -> BaseOutput:
                 if "error" in result:
                     success = False
                     msg = f'Output of "{cmd}" contains "error": {r.debug_msg()}'
+                    if not expects_blocked:
+                        logger.debug(
+                            f"iperf3 reported error: "
+                            f"client_pod={self.pod_name}, "
+                            f"server_pod={self.server.pod_name}, "
+                            f"server_port={self.server.port}, "
+                            f"error={result.get('error', '')!r}"
+                        )
 
             bitrate_gbps = _calculate_gbps(self.test_type, result)
             if success: