Print out name of logfile when debug test is run.
[riscv-tests.git] / debug / testlib.py
index df976df66ac1684ce85ae3e2d162e28c6cf567da..499f60da2351d281976c735b10227547a9655f58 100644 (file)
@@ -1,8 +1,11 @@
+import collections
 import os.path
+import random
 import re
 import shlex
 import subprocess
 import sys
+import tempfile
 import time
 import traceback
 
@@ -21,12 +24,12 @@ def find_file(path):
 def compile(args, xlen=32): # pylint: disable=redefined-builtin
     cc = os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gcc")
     cmd = [cc, "-g"]
-    if (xlen == 32):
+    if xlen == 32:
         cmd.append("-march=rv32imac")
         cmd.append("-mabi=ilp32")
     else:
         cmd.append("-march=rv64imac")
-        cmd.append("-mabi=lp64")        
+        cmd.append("-mabi=lp64")
     for arg in args:
         found = find_file(arg)
         if found:
@@ -55,19 +58,21 @@ def unused_port():
     return port
 
 class Spike(object):
-    logname = "spike.log"
+    logname = "spike-%d.log" % os.getpid()
 
-    def __init__(self, sim_cmd, binary=None, halted=False, with_jtag_gdb=True,
-            timeout=None, xlen=64):
+    def __init__(self, target, halted=False, timeout=None, with_jtag_gdb=True):
         """Launch spike. Return tuple of its process and the port it's running
         on."""
-        if sim_cmd:
-            cmd = shlex.split(sim_cmd)
+        if target.sim_cmd:
+            cmd = shlex.split(target.sim_cmd)
         else:
             spike = os.path.expandvars("$RISCV/bin/spike")
             cmd = [spike]
-        if xlen == 32:
-            cmd += ["--isa", "RV32"]
+        if target.xlen == 32:
+            cmd += ["--isa", "RV32G"]
+        else:
+            cmd += ["--isa", "RV64G"]
+        cmd += ["-m0x%x:0x%x" % (target.ram, target.ram_size)]
 
         if timeout:
             cmd = ["timeout", str(timeout)] + cmd
@@ -77,10 +82,10 @@ class Spike(object):
         if with_jtag_gdb:
             cmd += ['--rbb-port', '0']
             os.environ['REMOTE_BITBANG_HOST'] = 'localhost'
-        cmd.append("-m32")
-        cmd.append('programs/infinite_loop')
-        if binary:
-            cmd.append(binary)
+        self.infinite_loop = target.compile(
+                "programs/checksum.c", "programs/tiny-malloc.c",
+                "programs/infinite_loop.S", "-DDEFINE_MALLOC", "-DDEFINE_FREE")
+        cmd.append(self.infinite_loop)
         logfile = open(self.logname, "w")
         logfile.write("+ %s\n" % " ".join(cmd))
         logfile.flush()
@@ -111,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)
@@ -120,15 +127,21 @@ 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)
         done = False
         while not done:
+            # Fail if VCS exits early
+            exit_code = self.process.poll()
+            if exit_code is not None:
+                raise RuntimeError('VCS simulator exited early with status %d'
+                                   % exit_code)
+
             line = listenfile.readline()
             if not line:
                 time.sleep(1)
@@ -146,17 +159,18 @@ class VcsSim(object):
             pass
 
 class Openocd(object):
-    logname = "openocd.log"
+    logfile = tempfile.NamedTemporaryFile(prefix='openocd', suffix='.log')
+    logname = logfile.name
 
     def __init__(self, server_cmd=None, config=None, debug=False):
         if server_cmd:
             cmd = shlex.split(server_cmd)
         else:
-            openocd = os.path.expandvars("$RISCV/bin/riscv-openocd")
+            openocd = os.path.expandvars("$RISCV/bin/openocd")
             cmd = [openocd]
-            if (debug):
+            if debug:
                 cmd.append("-d")
-        
+
         # This command needs to come before any config scripts on the command
         # line, since they are executed in order.
         cmd += [
@@ -175,7 +189,7 @@ class Openocd(object):
         if config:
             f = find_file(config)
             if f is None:
-                print("Unable to read file " + config)
+                print "Unable to read file " + config
                 exit(1)
 
             cmd += ["-f", f]
@@ -195,51 +209,28 @@ class Openocd(object):
         messaged = False
         while True:
             log = open(Openocd.logname).read()
-            if "Ready for Remote Connections" in log:
+            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:
+                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..."
-
-        self.port = self._get_gdb_server_port()
-
-    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.")
+                print "Waiting for OpenOCD to start..."
+            if time.time() - start > 60:
+                raise Exception("ERROR: Timed out waiting for OpenOCD to "
+                        "listen for gdb")
 
     def __del__(self):
         try:
             self.process.kill()
             self.process.wait()
-        except OSError:
+        except (OSError, AttributeError):
             pass
 
 class OpenocdCli(object):
@@ -273,11 +264,17 @@ class CannotAccess(Exception):
         Exception.__init__(self)
         self.address = address
 
+Thread = collections.namedtuple('Thread', ('id', 'target_id', 'name',
+    'frame'))
+
 class Gdb(object):
+    logfile = tempfile.NamedTemporaryFile(prefix="gdb", suffix=".log")
+    logname = logfile.name
+
     def __init__(self,
             cmd=os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gdb")):
         self.child = pexpect.spawn(cmd)
-        self.child.logfile = open("gdb.log", "w")
+        self.child.logfile = open(self.logname, "w")
         self.child.logfile.write("+ %s\n" % cmd)
         self.wait()
         self.command("set confirm off")
@@ -296,13 +293,17 @@ class Gdb(object):
         self.child.expect(r"\(gdb\)", timeout=timeout)
         return self.child.before.strip()
 
-    def c(self, wait=True, timeout=-1):
+    def c(self, wait=True, timeout=-1, async=False):
+        if async:
+            async = "&"
+        else:
+            async = ""
         if wait:
-            output = self.command("c", timeout=timeout)
+            output = self.command("c%s" % async, timeout=timeout)
             assert "Continuing" in output
             return output
         else:
-            self.child.sendline("c")
+            self.child.sendline("c%s" % async)
             self.child.expect("Continuing")
 
     def interrupt(self):
@@ -336,7 +337,7 @@ class Gdb(object):
         return value
 
     def stepi(self):
-        output = self.command("stepi")
+        output = self.command("stepi", timeout=60)
         return output
 
     def load(self):
@@ -356,73 +357,128 @@ class Gdb(object):
         assert "Hardware assisted breakpoint" in output
         return output
 
-def run_all_tests(module, target, parsed):
-    good_results = set(('pass', 'not_applicable'))
+    def threads(self):
+        output = self.command("info threads")
+        threads = []
+        for line in output.splitlines():
+            m = re.match(
+                    r"[\s\*]*(\d+)\s*Thread (\d+)\s*\(Name: ([^\)]+)\s*(.*)",
+                    line)
+            if m:
+                threads.append(Thread(*m.groups()))
+        if not threads:
+            threads.append(Thread('1', '1', 'Default', '???'))
+        return threads
+
+    def thread(self, thread):
+        return self.command("thread %s" % thread.id)
 
-    start = time.time()
+def run_all_tests(module, target, parsed):
+    if not os.path.exists(parsed.logs):
+        os.makedirs(parsed.logs)
 
-    results = {}
-    count = 0
+    overall_start = time.time()
 
     global gdb_cmd  # pylint: disable=global-statement
     gdb_cmd = parsed.gdb
 
-    todo = [("ExamineTarget", ExamineTarget)]
+    todo = []
+    if parsed.misaval:
+        target.misa = int(parsed.misaval, 16)
+        print "Using $misa from command line: 0x%x" % target.misa
+    elif target.misa:
+        print "Using $misa from target definition: 0x%x" % target.misa
+    else:
+        todo.append(("ExamineTarget", ExamineTarget))
+
     for name in dir(module):
         definition = getattr(module, name)
         if type(definition) == type and hasattr(definition, 'test') and \
                 (not parsed.test or any(test in name for test in parsed.test)):
             todo.append((name, definition))
 
+    results, count = run_tests(parsed, target, todo)
+
+    header("ran %d tests in %.0fs" % (count, time.time() - overall_start),
+            dash=':')
+
+    return print_results(results)
+
+good_results = set(('pass', 'not_applicable'))
+def run_tests(parsed, target, todo):
+    results = {}
+    count = 0
+
     for name, definition in todo:
         instance = definition(target)
-        result = instance.run()
-        results.setdefault(result, []).append(name)
+        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 %s > %s ..." % (name, log_name),
+        sys.stdout.flush()
+        log_fd.write("Test: %s\n" % name)
+        log_fd.write("Target: %s\n" % type(target).__name__)
+        start = time.time()
+        real_stdout = sys.stdout
+        sys.stdout = log_fd
+        try:
+            result = instance.run()
+            log_fd.write("Result: %s\n" % result)
+        finally:
+            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, log_name))
         count += 1
         if result not in good_results and parsed.fail_fast:
             break
 
-    header("ran %d tests in %.0fs" % (count, time.time() - start), dash=':')
+    return results, count
 
+def print_results(results):
     result = 0
     for key, value in results.iteritems():
         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",
             help="The command to use to start gdb.")
+    parser.add_argument("--misaval",
+            help="Don't run ExamineTarget, just assume the misa value which is "
+            "specified.")
 
-def header(title, dash='-'):
+def header(title, dash='-', length=78):
     if title:
-        dashes = dash * (36 - len(title))
+        dashes = dash * (length - 4 - len(title))
         before = dashes[:len(dashes)/2]
         after = dashes[len(dashes)/2:]
         print "%s[ %s ]%s" % (before, title, after)
     else:
-        print dash * 40
+        print dash * length
 
 def print_log(path):
     header(path)
     lines = open(path, "r").readlines()
-    if len(lines) > 1000:
-        for l in lines[:500]:
-            sys.stdout.write(l)
-        print "..."
-        for l in lines[-500:]:
-            sys.stdout.write(l)
-    else:
-        for l in lines:
-            sys.stdout.write(l)
+    for l in lines:
+        sys.stdout.write(l)
+    print
 
 class BaseTest(object):
     compiled = {}
@@ -455,9 +511,16 @@ class BaseTest(object):
 
     def classSetup(self):
         self.compile()
-        self.target_process = self.target.target()
-        self.server = self.target.server()
-        self.logs.append(self.server.logname)
+        self.target_process = self.target.create()
+        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
@@ -473,18 +536,15 @@ class BaseTest(object):
         if an exception is raised.
         """
 
-        print "Running", type(self).__name__, "...",
         sys.stdout.flush()
 
         if not self.early_applicable():
-            print "not_applicable"
             return "not_applicable"
 
         self.start = time.time()
 
-        self.classSetup()
-
         try:
+            self.classSetup()
             self.setup()
             result = self.test()    # pylint: disable=no-member
         except TestNotApplicable:
@@ -494,24 +554,21 @@ class BaseTest(object):
                 result = "fail"
             else:
                 result = "exception"
-            print "%s in %.2fs" % (result, time.time() - self.start)
-            print "=" * 40
             if isinstance(e, TestFailed):
                 header("Message")
                 print e.message
             header("Traceback")
             traceback.print_exc(file=sys.stdout)
-            for log in self.logs:
-                print_log(log)
-            print "/" * 40
             return result
 
         finally:
+            for log in self.logs:
+                print_log(log)
+            header("End of logs")
             self.classTeardown()
 
         if not result:
             result = 'pass'
-        print "%s in %.2fs" % (result, time.time() - self.start)
         return result
 
 gdb_cmd = None
@@ -522,13 +579,14 @@ class GdbTest(BaseTest):
 
     def classSetup(self):
         BaseTest.classSetup(self)
-        self.logs.append("gdb.log")
 
         if gdb_cmd:
             self.gdb = Gdb(gdb_cmd)
         else:
             self.gdb = Gdb()
 
+        self.logs.append(self.gdb.logname)
+
         if self.binary:
             self.gdb.command("file %s" % self.binary)
         if self.target:
@@ -537,8 +595,16 @@ class GdbTest(BaseTest):
         if self.server.port:
             self.gdb.command(
                     "target extended-remote localhost:%d" % self.server.port)
+            # Select a random thread.
+            # TODO: Allow a command line option to force a specific thread.
+            thread = random.choice(self.gdb.threads())
+            self.gdb.thread(thread)
+
+        for cmd in self.target.gdb_setup:
+            self.gdb.command(cmd)
 
-        self.gdb.p("$priv=3")
+        # FIXME: OpenOCD doesn't handle PRIV now
+        #self.gdb.p("$priv=3")
 
     def classTeardown(self):
         del self.gdb
@@ -556,7 +622,8 @@ class ExamineTarget(GdbTest):
         elif (self.target.misa >> 126) == 3:
             txt += "128"
         else:
-            txt += "??"
+            raise TestFailed("Couldn't determine XLEN from $misa (0x%x)" %
+                    self.target.misa)
 
         for i in range(26):
             if self.target.misa & (1<<i):