When a test fails with exception, actually print out the reason why.
[riscv-tests.git] / debug / testlib.py
index f511088cf53e81c8fb9607db2c7aa3405e6d2b48..b81b4cdd7806358773e5c926d77eb22f3a7f15ec 100644 (file)
@@ -116,6 +116,8 @@ class Spike(object):
         return self.process.wait(*args, **kwargs)
 
 class VcsSim(object):
+    logname = "simv.log"
+
     def __init__(self, sim_cmd=None, debug=False):
         if sim_cmd:
             cmd = shlex.split(sim_cmd)
@@ -125,10 +127,10 @@ class VcsSim(object):
         if debug:
             cmd[0] = cmd[0] + "-debug"
             cmd += ["+vcdplusfile=output/gdbserver.vpd"]
-        logfile = open("simv.log", "w")
+        logfile = open(self.logname, "w")
         logfile.write("+ %s\n" % " ".join(cmd))
         logfile.flush()
-        listenfile = open("simv.log", "r")
+        listenfile = open(self.logname, "r")
         listenfile.seek(0, 2)
         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
                 stdout=logfile, stderr=logfile)
@@ -200,63 +202,36 @@ class Openocd(object):
         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
                 stdout=logfile, stderr=logfile)
 
-        # Wait for OpenOCD to have made it through riscv_examine(). When using
-        # OpenOCD to communicate with a simulator this may take a long time,
-        # and gdb will time out when trying to connect if we attempt too early.
-        start = time.time()
-        messaged = False
-        while True:
-            log = open(Openocd.logname).read()
-            if "Ready for Remote Connections" in log:
-                break
-            if not self.process.poll() is None:
-                header("OpenOCD log")
-                sys.stdout.write(log)
-                raise Exception(
-                        "OpenOCD exited before completing riscv_examine()")
-            if not messaged and time.time() - start > 1:
-                messaged = True
-                print "Waiting for OpenOCD to examine RISCV core..."
-            if time.time() - start > 60:
-                raise Exception("ERROR: Timed out waiting for OpenOCD to "
-                        "examine RISCV core")
-
         try:
-            self.port = self._get_gdb_server_port()
-        except:
+            # Wait for OpenOCD to have made it through riscv_examine(). When
+            # using OpenOCD to communicate with a simulator this may take a
+            # long time, and gdb will time out when trying to connect if we
+            # attempt too early.
+            start = time.time()
+            messaged = False
+            while True:
+                log = open(Openocd.logname).read()
+                m = re.search(r"Listening on port (\d+) for gdb connections",
+                        log)
+                if m:
+                    self.port = int(m.group(1))
+                    break
+
+                if not self.process.poll() is None:
+                    raise Exception(
+                            "OpenOCD exited before completing riscv_examine()")
+                if not messaged and time.time() - start > 1:
+                    messaged = True
+                    print "Waiting for OpenOCD to start..."
+                if time.time() - start > 60:
+                    raise Exception("ERROR: Timed out waiting for OpenOCD to "
+                            "listen for gdb")
+
+        except Exception:
             header("OpenOCD log")
             sys.stdout.write(log)
             raise
 
-    def _get_gdb_server_port(self):
-        """Get port that OpenOCD's gdb server is listening on."""
-        MAX_ATTEMPTS = 50
-        PORT_REGEX = re.compile(r'(?P<port>\d+) \(LISTEN\)')
-        for _ in range(MAX_ATTEMPTS):
-            with open(os.devnull, 'w') as devnull:
-                try:
-                    output = subprocess.check_output([
-                        'lsof',
-                        '-a',  # Take the AND of the following selectors
-                        '-p{}'.format(self.process.pid),  # Filter on PID
-                        '-iTCP',  # Filter only TCP sockets
-                    ], stderr=devnull)
-                except subprocess.CalledProcessError:
-                    output = ""
-            matches = list(PORT_REGEX.finditer(output))
-            matches = [m for m in matches
-                    if m.group('port') not in ('6666', '4444')]
-            if len(matches) > 1:
-                print output
-                raise Exception(
-                    "OpenOCD listening on multiple ports. Cannot uniquely "
-                    "identify gdb server port.")
-            elif matches:
-                [match] = matches
-                return int(match.group('port'))
-            time.sleep(1)
-        raise Exception("Timed out waiting for gdb server to obtain port.")
-
     def __del__(self):
         try:
             self.process.kill()
@@ -368,7 +343,7 @@ class Gdb(object):
         return value
 
     def stepi(self):
-        output = self.command("stepi")
+        output = self.command("stepi", timeout=60)
         return output
 
     def load(self):
@@ -445,7 +420,7 @@ def run_tests(parsed, target, todo):
         log_name = os.path.join(parsed.logs, "%s-%s-%s.log" %
                 (time.strftime("%Y%m%d-%H%M%S"), type(target).__name__, name))
         log_fd = open(log_name, 'w')
-        print "Running", name, "...",
+        print "Running %s > %s ..." % (name, log_name),
         sys.stdout.flush()
         log_fd.write("Test: %s\n" % name)
         log_fd.write("Target: %s\n" % type(target).__name__)
@@ -459,8 +434,10 @@ def run_tests(parsed, target, todo):
             sys.stdout = real_stdout
             log_fd.write("Time elapsed: %.2fs\n" % (time.time() - start))
         print "%s in %.2fs" % (result, time.time() - start)
+        if result not in good_results and parsed.print_failures:
+            sys.stdout.write(open(log_name).read())
         sys.stdout.flush()
-        results.setdefault(result, []).append(name)
+        results.setdefault(result, []).append((name, log_name))
         count += 1
         if result not in good_results and parsed.fail_fast:
             break
@@ -473,17 +450,18 @@ def print_results(results):
         print "%d tests returned %s" % (len(value), key)
         if key not in good_results:
             result = 1
-            for test in value:
-                print "   ", test
+            for name, log_name in value:
+                print "   %s > %s" % (name, log_name)
 
     return result
 
 def add_test_run_options(parser):
-
     parser.add_argument("--logs", default="logs",
             help="Store logs in the specified directory.")
     parser.add_argument("--fail-fast", "-f", action="store_true",
             help="Exit as soon as any test fails.")
+    parser.add_argument("--print-failures", action="store_true",
+            help="When a test fails, print the log file to stdout.")
     parser.add_argument("test", nargs='*',
             help="Run only tests that are named here.")
     parser.add_argument("--gdb",
@@ -540,8 +518,15 @@ class BaseTest(object):
     def classSetup(self):
         self.compile()
         self.target_process = self.target.create()
-        self.server = self.target.server()
-        self.logs.append(self.server.logname)
+        if self.target_process:
+            self.logs.append(self.target_process.logname)
+        try:
+            self.server = self.target.server()
+            self.logs.append(self.server.logname)
+        except Exception:
+            for log in self.logs:
+                print_log(log)
+            raise
 
     def classTeardown(self):
         del self.server
@@ -564,9 +549,8 @@ class BaseTest(object):
 
         self.start = time.time()
 
-        self.classSetup()
-
         try:
+            self.classSetup()
             self.setup()
             result = self.test()    # pylint: disable=no-member
         except TestNotApplicable:
@@ -576,6 +560,8 @@ class BaseTest(object):
                 result = "fail"
             else:
                 result = "exception"
+                header ("Backtrace")
+                print e
             if isinstance(e, TestFailed):
                 header("Message")
                 print e.message
@@ -622,6 +608,9 @@ class GdbTest(BaseTest):
             thread = random.choice(self.gdb.threads())
             self.gdb.thread(thread)
 
+        for cmd in self.target.gdb_setup:
+            self.gdb.command(cmd)
+
         # FIXME: OpenOCD doesn't handle PRIV now
         #self.gdb.p("$priv=3")