make test: Add exception handling around subprocess.

This cleans up exception catching to identify oserrors.  By raising the
specific exception closer to the offending call, we get additional stack history
and can add clearer error logging to assist in troubleshooting.

Change-Id: I592e4d46844b822a816485bf54910f8daed92088
Signed-off-by: Paul Vinciguerra <pvinci@vinciconsulting.com>

diff --git a/test/framework.py b/test/framework.py
index 13f94d6..38a4985 100644 (file)
--- a/test/framework.py
+++ b/test/framework.py
@@ -367,7 +367,16 @@ class VppTestCase(unittest.TestCase):
                                        stderr=subprocess.PIPE,
                                        bufsize=1)
         except subprocess.CalledProcessError as e:
-            cls.logger.critical("Couldn't start vpp: %s" % e)
+            cls.logger.critical("Subprocess returned with non-0 return code: ("
+                                "%s)", e.returncode)
+            raise
+        except OSError as e:
+            cls.logger.critical("Subprocess returned with OS error: "
+                                "(%s) %s", e.errno, e.strerror)
+            raise
+        except Exception as e:
+            cls.logger.exception("Subprocess returned unexpected from "
+                                 "%s:", cmdline)
             raise
 
         cls.wait_for_enter()

diff --git a/test/hook.py b/test/hook.py
index cddb603..d23604b 100644 (file)
--- a/test/hook.py
+++ b/test/hook.py
@@ -84,17 +84,28 @@ class PollHook(Hook):
         super(PollHook, self).__init__(test)
 
     def on_crash(self, core_path):
-        self.logger.error("Core file present, debug with: gdb %s %s" %
-                          (self.test.vpp_bin, core_path))
+        self.logger.error("Core file present, debug with: gdb %s %s",
+                          self.testcase.vpp_bin, core_path)
         check_core_path(self.logger, core_path)
-        self.logger.error("Running `file %s':" % core_path)
+        self.logger.error("Running `file %s':", core_path)
         try:
             info = check_output(["file", core_path])
             self.logger.error(info)
         except CalledProcessError as e:
             self.logger.error(
-                "Could not run `file' utility on core-file, "
-                "rc=%s" % e.returncode)
+                "Subprocess returned with error running `file' utility on "
+                "core-file, "
+                "rc=%s",  e.returncode)
+        except OSError as e:
+            self.logger.error(
+                "Subprocess returned OS error running `file' utility on "
+                "core-file, "
+                "oserror=(%s) %s", e.errno, e.strerror)
+        except Exception as e:
+            self.logger.error(
+                "Subprocess returned unanticipated error running `file' "
+                "utility on core-file, "
+                "%s", e)
 
     def poll_vpp(self):
         """

diff --git a/test/run_tests.py b/test/run_tests.py
index 726ccc9..f5d0d35 100644 (file)
--- a/test/run_tests.py
+++ b/test/run_tests.py
@@ -253,13 +253,23 @@ def handle_failed_suite(logger, last_test_temp_dir, vpp_pid):
                 "Core-file exists in test temporary directory: %s!" %
                 core_path)
             check_core_path(logger, core_path)
-            logger.debug("Running `file %s':" % core_path)
+            logger.debug("Running 'file %s':" % core_path)
             try:
                 info = check_output(["file", core_path])
                 logger.debug(info)
             except CalledProcessError as e:
-                logger.error("Could not run `file' utility on core-file, "
-                             "rc=%s" % e.returncode)
+                logger.error("Subprocess returned with return code "
+                             "while running `file' utility on core-file "
+                             "returned: "
+                             "rc=%s", e.returncode)
+            except OSError as e:
+                logger.error("Subprocess returned with OS error while "
+                             "running 'file' utility "
+                             "on core-file: "
+                             "(%s) %s", e.errno, e.strerror)
+            except Exception as e:
+                logger.exception("Unexpected error running `file' utility "
+                                 "on core-file")
 
     if vpp_pid:
         # Copy api post mortem

diff --git a/test/test_vcl.py b/test/test_vcl.py
index 0901712..0a971a5 100644 (file)
--- a/test/test_vcl.py
+++ b/test/test_vcl.py
@@ -276,9 +276,20 @@ class LDPCutThruTestCase(VCLTestCase):
         try:
             subprocess.check_output(['iperf3', '-v'])
         except subprocess.CalledProcessError:
-            self.logger.error("WARNING: 'iperf3' is not installed,")
+            self.logger.error(
+                "WARNING: Subprocess returned non-0 running 'iperf3 -v")
+            self.logger.error("         'test_ldp_cut_thru_iperf3' not run!")
+            return
+        except OSError as e:
+            self.logger.error(
+                "WARNING: Subprocess returned with OS error (%s) %s\n"
+                "         'iperf3' is likely not installed,",
+                e.errno, e.strerror)
             self.logger.error("         'test_ldp_cut_thru_iperf3' not run!")
             return
+        except Exception:
+            self.logger.exception(
+                "Subprocess returned non-0 running 'iperf3 -v")
 
         self.timeout = self.client_iperf3_timeout
         self.cut_thru_test("iperf3", self.server_iperf3_args,
@@ -652,6 +663,14 @@ class LDPThruHostStackIperf(VCLTestCase):
             self.logger.error(
                 "         'test_ldp_thru_host_stack_iperf3' not run!")
             return
+        except OSError as e:
+            self.logger.error("WARNING: 'iperf3' is not installed,")
+            self.logger.error("         'test' not run!")
+            return
+        except Exception as e:
+            self.logger.error("WARNING: 'iperf3' unexpected error,")
+            self.logger.error("         'test' not run!")
+            return
 
         self.timeout = self.client_iperf3_timeout
         self.thru_host_stack_test("iperf3", self.server_iperf3_args,