debug: Allow OpenOCD startup timeout to be specified. Print out path to log files.
[riscv-tests.git] / debug / testlib.py
index ce2ec2e16d7675b4c410bde62986753663aa1ffc..d860533e50b4bad596aaa6c24fa1505ba97410a6 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)
@@ -159,8 +161,9 @@ class VcsSim(object):
 class Openocd(object):
     logfile = tempfile.NamedTemporaryFile(prefix='openocd', suffix='.log')
     logname = logfile.name
+    print "OpenOCD Temp Logfile: %s " % logname
 
-    def __init__(self, server_cmd=None, config=None, debug=False):
+    def __init__(self, server_cmd=None, config=None, debug=False, timeout=60):
         if server_cmd:
             cmd = shlex.split(server_cmd)
         else:
@@ -194,69 +197,42 @@ class Openocd(object):
         if debug:
             cmd.append("-d")
 
-        logfile = open(Openocd.logname, "w")
+        logfile = Openocd.logfile
         logfile.write("+ %s\n" % " ".join(cmd))
         logfile.flush()
         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) > timeout:
+                    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()
@@ -301,11 +277,11 @@ Thread = collections.namedtuple('Thread', ('id', 'target_id', 'name',
 class Gdb(object):
     logfile = tempfile.NamedTemporaryFile(prefix="gdb", suffix=".log")
     logname = logfile.name
+    print "GDB Temporary file: %s" % logname
 
     def __init__(self,
             cmd=os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gdb")):
         self.child = pexpect.spawn(cmd)
-        self.child.logfile = open(self.logname, "w")
         self.child.logfile.write("+ %s\n" % cmd)
         self.wait()
         self.command("set confirm off")
@@ -368,7 +344,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 +421,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 +435,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 +451,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",
@@ -582,6 +561,8 @@ class BaseTest(object):
                 result = "fail"
             else:
                 result = "exception"
+                header ("Backtrace")
+                print e
             if isinstance(e, TestFailed):
                 header("Message")
                 print e.message