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>

4 files changed, 59 insertions, 10 deletions

diff --git a/test/framework.py b/test/framework.py
index 13f94d66354..38a49859e14 100644
--- 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 cddb603e46e..d23604ba13f 100644
--- 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 726ccc9c0f4..f5d0d3546a2 100644
--- 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 09017127eba..0a971a59a78 100644
--- 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,