Print out name of logfile when debug test is run.
[riscv-tests.git] / debug / testlib.py
index 76989806b8ff57278c341c0776a3bb754dd4384e..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
 
@@ -19,17 +22,31 @@ def find_file(path):
     return None
 
 def compile(args, xlen=32): # pylint: disable=redefined-builtin
-    cc = os.path.expandvars("$RISCV/bin/riscv%d-unknown-elf-gcc" % xlen)
+    cc = os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gcc")
     cmd = [cc, "-g"]
+    if xlen == 32:
+        cmd.append("-march=rv32imac")
+        cmd.append("-mabi=ilp32")
+    else:
+        cmd.append("-march=rv64imac")
+        cmd.append("-mabi=lp64")
     for arg in args:
         found = find_file(arg)
         if found:
             cmd.append(found)
         else:
             cmd.append(arg)
-    cmd = " ".join(cmd)
-    result = os.system(cmd)
-    assert result == 0, "%r failed" % cmd
+    process = subprocess.Popen(cmd, stdout=subprocess.PIPE,
+                               stderr=subprocess.PIPE)
+    stdout, stderr = process.communicate()
+    if process.returncode:
+        print
+        header("Compile failed")
+        print "+", " ".join(cmd)
+        print stdout,
+        print stderr,
+        header("")
+        raise Exception("Compile failed!")
 
 def unused_port():
     # http://stackoverflow.com/questions/2838244/get-open-tcp-port-in-python/2838309#2838309
@@ -41,37 +58,53 @@ def unused_port():
     return port
 
 class Spike(object):
-    logname = "spike.log"
+    logname = "spike-%d.log" % os.getpid()
 
-    def __init__(self, cmd, binary=None, halted=False, with_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 cmd:
-            cmd = shlex.split(cmd)
+        if target.sim_cmd:
+            cmd = shlex.split(target.sim_cmd)
         else:
-            cmd = ["spike"]
-        if xlen == 32:
-            cmd += ["--isa", "RV32"]
+            spike = os.path.expandvars("$RISCV/bin/spike")
+            cmd = [spike]
+        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
 
         if halted:
             cmd.append('-H')
-        if with_gdb:
-            self.port = unused_port()
-            cmd += ['--gdb-port', str(self.port)]
-        cmd.append("-m32")
-        cmd.append('pk')
-        if binary:
-            cmd.append(binary)
+        if with_jtag_gdb:
+            cmd += ['--rbb-port', '0']
+            os.environ['REMOTE_BITBANG_HOST'] = 'localhost'
+        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()
         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
                 stdout=logfile, stderr=logfile)
 
+        if with_jtag_gdb:
+            self.port = None
+            for _ in range(30):
+                m = re.search(r"Listening for remote bitbang connection on "
+                        r"port (\d+).", open(self.logname).read())
+                if m:
+                    self.port = int(m.group(1))
+                    os.environ['REMOTE_BITBANG_PORT'] = m.group(1)
+                    break
+                time.sleep(0.11)
+            assert self.port, "Didn't get spike message about bitbang " \
+                    "connection"
+
     def __del__(self):
         try:
             self.process.kill()
@@ -83,24 +116,32 @@ class Spike(object):
         return self.process.wait(*args, **kwargs)
 
 class VcsSim(object):
-    def __init__(self, simv=None, debug=False):
-        if simv:
-            cmd = shlex.split(simv)
+    logname = "simv.log"
+
+    def __init__(self, sim_cmd=None, debug=False):
+        if sim_cmd:
+            cmd = shlex.split(sim_cmd)
         else:
             cmd = ["simv"]
         cmd += ["+jtag_vpi_enable"]
         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)
@@ -108,7 +149,7 @@ class VcsSim(object):
             if match:
                 done = True
                 self.port = int(match.group(1))
-                print "Using port %d for JTAG VPI" % self.port
+                os.environ['JTAG_VPI_PORT'] = str(self.port)
 
     def __del__(self):
         try:
@@ -118,33 +159,48 @@ class VcsSim(object):
             pass
 
 class Openocd(object):
-    logname = "openocd.log"
+    logfile = tempfile.NamedTemporaryFile(prefix='openocd', suffix='.log')
+    logname = logfile.name
 
-    def __init__(self, cmd=None, config=None, debug=False):
-        if cmd:
-            cmd = shlex.split(cmd)
+    def __init__(self, server_cmd=None, config=None, debug=False):
+        if server_cmd:
+            cmd = shlex.split(server_cmd)
         else:
-            cmd = ["openocd"]
-        if config:
-            cmd += ["-f", find_file(config)]
-        if debug:
-            cmd.append("-d")
+            openocd = os.path.expandvars("$RISCV/bin/openocd")
+            cmd = [openocd]
+            if debug:
+                cmd.append("-d")
 
-        # Assign port
-        self.port = unused_port()
-        print "Using port %d for gdb server" % self.port
         # This command needs to come before any config scripts on the command
         # line, since they are executed in order.
-        cmd[1:1] = ["--command", "gdb_port %d" % self.port]
+        cmd += [
+            # Tell OpenOCD to bind gdb to an unused, ephemeral port.
+            "--command",
+            "gdb_port 0",
+            # Disable tcl and telnet servers, since they are unused and because
+            # the port numbers will conflict if multiple OpenOCD processes are
+            # running on the same server.
+            "--command",
+            "tcl_port disabled",
+            "--command",
+            "telnet_port disabled",
+        ]
 
-        env = os.environ.copy()
-        env['JTAG_VPI_PORT'] = str(otherProcess.port)
+        if config:
+            f = find_file(config)
+            if f is None:
+                print "Unable to read file " + config
+                exit(1)
+
+            cmd += ["-f", f]
+        if debug:
+            cmd.append("-d")
 
         logfile = open(Openocd.logname, "w")
         logfile.write("+ %s\n" % " ".join(cmd))
         logfile.flush()
         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
-                stdout=logfile, stderr=logfile, env=env)
+                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,
@@ -153,43 +209,72 @@ class Openocd(object):
         messaged = False
         while True:
             log = open(Openocd.logname).read()
-            if "Examined RISCV core" 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..."
+                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):
     def __init__(self, port=4444):
-        self.child = pexpect.spawn("sh -c 'telnet localhost %d | tee openocd-cli.log'" % port)
+        self.child = pexpect.spawn(
+                "sh -c 'telnet localhost %d | tee openocd-cli.log'" % port)
         self.child.expect("> ")
 
     def command(self, cmd):
         self.child.sendline(cmd)
+        self.child.expect(cmd)
         self.child.expect("\n")
         self.child.expect("> ")
-        return self.child.before.strip()
+        return self.child.before.strip("\t\r\n \0")
+
+    def reg(self, reg=''):
+        output = self.command("reg %s" % reg)
+        matches = re.findall(r"(\w+) \(/\d+\): (0x[0-9A-F]+)", output)
+        values = {r: int(v, 0) for r, v in matches}
+        if reg:
+            return values[reg]
+        return values
+
+    def load_image(self, image):
+        output = self.command("load_image %s" % image)
+        if 'invalid ELF file, only 32bits files are supported' in output:
+            raise TestNotApplicable(output)
 
 class CannotAccess(Exception):
     def __init__(self, address):
         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")
@@ -202,24 +287,28 @@ class Gdb(object):
         """Wait for prompt."""
         self.child.expect(r"\(gdb\)")
 
-    def command(self, command, timeout=-1):
+    def command(self, command, timeout=6000):
         self.child.sendline(command)
         self.child.expect("\n", timeout=timeout)
         self.child.expect(r"\(gdb\)", timeout=timeout)
         return self.child.before.strip()
 
-    def c(self, wait=True):
+    def c(self, wait=True, timeout=-1, async=False):
+        if async:
+            async = "&"
+        else:
+            async = ""
         if wait:
-            output = self.command("c")
+            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):
         self.child.send("\003")
-        self.child.expect(r"\(gdb\)", timeout=60)
+        self.child.expect(r"\(gdb\)", timeout=6000)
         return self.child.before.strip()
 
     def x(self, address, size='w'):
@@ -227,6 +316,13 @@ class Gdb(object):
         value = int(output.split(':')[1].strip(), 0)
         return value
 
+    def p_raw(self, obj):
+        output = self.command("p %s" % obj)
+        m = re.search("Cannot access memory at address (0x[0-9a-f]+)", output)
+        if m:
+            raise CannotAccess(int(m.group(1), 0))
+        return output.split('=')[-1].strip()
+
     def p(self, obj):
         output = self.command("p/x %s" % obj)
         m = re.search("Cannot access memory at address (0x[0-9a-f]+)", output)
@@ -241,11 +337,11 @@ class Gdb(object):
         return value
 
     def stepi(self):
-        output = self.command("stepi")
+        output = self.command("stepi", timeout=60)
         return output
 
     def load(self):
-        output = self.command("load", timeout=60)
+        output = self.command("load", timeout=6000)
         assert "failed" not in  output
         assert "Transfer rate" in output
 
@@ -261,51 +357,131 @@ class Gdb(object):
         assert "Hardware assisted breakpoint" in output
         return output
 
-def run_all_tests(module, target, tests, fail_fast):
-    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)
+
+def run_all_tests(module, target, parsed):
+    if not os.path.exists(parsed.logs):
+        os.makedirs(parsed.logs)
+
+    overall_start = time.time()
+
+    global gdb_cmd  # pylint: disable=global-statement
+    gdb_cmd = parsed.gdb
+
+    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))
 
-    start = time.time()
-
-    results = {}
-    count = 0
     for name in dir(module):
         definition = getattr(module, name)
         if type(definition) == type and hasattr(definition, 'test') and \
-                (not tests or any(test in name for test in tests)):
-            instance = definition(target)
+                (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)
+        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()
-            results.setdefault(result, []).append(name)
-            count += 1
-            if result not in good_results and fail_fast:
-                break
+            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.")
-
-def header(title, dash='-'):
-    dashes = dash * (36 - len(title))
-    before = dashes[:len(dashes)/2]
-    after = dashes[len(dashes)/2:]
-    print "%s[ %s ]%s" % (before, title, after)
+    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='-', length=78):
+    if 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 * length
+
+def print_log(path):
+    header(path)
+    lines = open(path, "r").readlines()
+    for l in lines:
+        sys.stdout.write(l)
+    print
 
 class BaseTest(object):
     compiled = {}
-    logs = []
 
     def __init__(self, target):
         self.target = target
@@ -313,6 +489,7 @@ class BaseTest(object):
         self.target_process = None
         self.binary = None
         self.start = 0
+        self.logs = []
 
     def early_applicable(self):
         """Return a false value if the test has determined it cannot run
@@ -327,25 +504,23 @@ class BaseTest(object):
         compile_args = getattr(self, 'compile_args', None)
         if compile_args:
             if compile_args not in BaseTest.compiled:
-                try:
-                    # pylint: disable=star-args
-                    BaseTest.compiled[compile_args] = \
-                            self.target.compile(*compile_args)
-                except Exception: # pylint: disable=broad-except
-                    print "exception while compiling in %.2fs" % (
-                            time.time() - self.start)
-                    print "=" * 40
-                    header("Traceback")
-                    traceback.print_exc(file=sys.stdout)
-                    print "/" * 40
-                    return "exception"
+                # pylint: disable=star-args
+                BaseTest.compiled[compile_args] = \
+                        self.target.compile(*compile_args)
         self.binary = BaseTest.compiled.get(compile_args)
 
     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
@@ -361,51 +536,110 @@ 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:
+            result = "not_applicable"
         except Exception as e: # pylint: disable=broad-except
             if isinstance(e, TestFailed):
                 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:
-                header(log)
-                print open(log, "r").read()
-            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
+class GdbTest(BaseTest):
+    def __init__(self, target):
+        BaseTest.__init__(self, target)
+        self.gdb = None
+
+    def classSetup(self):
+        BaseTest.classSetup(self)
+
+        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:
+            self.gdb.command("set arch riscv:rv%d" % self.target.xlen)
+            self.gdb.command("set remotetimeout %d" % self.target.timeout_sec)
+        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)
+
+        # FIXME: OpenOCD doesn't handle PRIV now
+        #self.gdb.p("$priv=3")
+
+    def classTeardown(self):
+        del self.gdb
+        BaseTest.classTeardown(self)
+
+class ExamineTarget(GdbTest):
+    def test(self):
+        self.target.misa = self.gdb.p("$misa")
+
+        txt = "RV"
+        if (self.target.misa >> 30) == 1:
+            txt += "32"
+        elif (self.target.misa >> 62) == 2:
+            txt += "64"
+        elif (self.target.misa >> 126) == 3:
+            txt += "128"
+        else:
+            raise TestFailed("Couldn't determine XLEN from $misa (0x%x)" %
+                    self.target.misa)
+
+        for i in range(26):
+            if self.target.misa & (1<<i):
+                txt += chr(i + ord('A'))
+        print txt,
+
 class TestFailed(Exception):
     def __init__(self, message):
         Exception.__init__(self)
         self.message = message
 
+class TestNotApplicable(Exception):
+    def __init__(self, message):
+        Exception.__init__(self)
+        self.message = message
+
 def assertEqual(a, b):
     if a != b:
         raise TestFailed("%r != %r" % (a, b))
@@ -426,6 +660,10 @@ def assertGreater(a, b):
     if not a > b:
         raise TestFailed("%r not greater than %r" % (a, b))
 
+def assertLess(a, b):
+    if not a < b:
+        raise TestFailed("%r not less than %r" % (a, b))
+
 def assertTrue(a):
     if not a:
         raise TestFailed("%r is not True" % a)