debug/testlib.py

   1 import collections
   2 import os.path
   3 import random
   4 import re
   5 import shlex
   6 import subprocess
   7 import sys
   8 import tempfile
   9 import time
  10 import traceback
  11
  12 import pexpect
  13
  14 # Note that gdb comes with its own testsuite. I was unable to figure out how to
  15 # run that testsuite against the spike simulator.
  16
  17 def find_file(path):
  18     for directory in (os.getcwd(), os.path.dirname(__file__)):
  19         fullpath = os.path.join(directory, path)
  20         if os.path.exists(fullpath):
  21             return fullpath
  22     return None
  23
  24 def compile(args, xlen=32): # pylint: disable=redefined-builtin
  25     cc = os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gcc")
  26     cmd = [cc, "-g"]
  27     if xlen == 32:
  28         cmd.append("-march=rv32imac")
  29         cmd.append("-mabi=ilp32")
  30     else:
  31         cmd.append("-march=rv64imac")
  32         cmd.append("-mabi=lp64")
  33     for arg in args:
  34         found = find_file(arg)
  35         if found:
  36             cmd.append(found)
  37         else:
  38             cmd.append(arg)
  39     header("Compile")
  40     print "+", " ".join(cmd)
  41     process = subprocess.Popen(cmd, stdout=subprocess.PIPE,
  42                                stderr=subprocess.PIPE)
  43     stdout, stderr = process.communicate()
  44     if process.returncode:
  45         print stdout,
  46         print stderr,
  47         header("")
  48         raise Exception("Compile failed!")
  49
  50 def unused_port():
  51     # http://stackoverflow.com/questions/2838244/get-open-tcp-port-in-python/2838309#2838309
  52     import socket
  53     s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
  54     s.bind(("", 0))
  55     port = s.getsockname()[1]
  56     s.close()
  57     return port
  58
  59 class Spike(object):
  60     logname = "spike-%d.log" % os.getpid()
  61
  62     def __init__(self, target, halted=False, timeout=None, with_jtag_gdb=True):
  63         """Launch spike. Return tuple of its process and the port it's running
  64         on."""
  65         self.process = None
  66
  67         if target.harts:
  68             harts = target.harts
  69         else:
  70             harts = [target]
  71
  72         if target.sim_cmd:
  73             cmd = shlex.split(target.sim_cmd)
  74         else:
  75             spike = os.path.expandvars("$RISCV/bin/spike")
  76             cmd = [spike]
  77
  78         cmd += ["-p%d" % len(harts)]
  79
  80         assert len(set(t.xlen for t in harts)) == 1, \
  81                 "All spike harts must have the same XLEN"
  82
  83         if harts[0].xlen == 32:
  84             cmd += ["--isa", "RV32G"]
  85         else:
  86             cmd += ["--isa", "RV64G"]
  87
  88         assert len(set(t.ram for t in harts)) == 1, \
  89                 "All spike harts must have the same RAM layout"
  90         assert len(set(t.ram_size for t in harts)) == 1, \
  91                 "All spike harts must have the same RAM layout"
  92         cmd += ["-m0x%x:0x%x" % (harts[0].ram, harts[0].ram_size)]
  93
  94         if timeout:
  95             cmd = ["timeout", str(timeout)] + cmd
  96
  97         if halted:
  98             cmd.append('-H')
  99         if with_jtag_gdb:
 100             cmd += ['--rbb-port', '0']
 101             os.environ['REMOTE_BITBANG_HOST'] = 'localhost'
 102         self.infinite_loop = harts[0].compile(
 103                 "programs/checksum.c", "programs/tiny-malloc.c",
 104                 "programs/infinite_loop.S", "-DDEFINE_MALLOC", "-DDEFINE_FREE")
 105         cmd.append(self.infinite_loop)
 106         logfile = open(self.logname, "w")
 107         logfile.write("+ %s\n" % " ".join(cmd))
 108         logfile.flush()
 109         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
 110                 stdout=logfile, stderr=logfile)
 111
 112         if with_jtag_gdb:
 113             self.port = None
 114             for _ in range(30):
 115                 m = re.search(r"Listening for remote bitbang connection on "
 116                         r"port (\d+).", open(self.logname).read())
 117                 if m:
 118                     self.port = int(m.group(1))
 119                     os.environ['REMOTE_BITBANG_PORT'] = m.group(1)
 120                     break
 121                 time.sleep(0.11)
 122             assert self.port, "Didn't get spike message about bitbang " \
 123                     "connection"
 124
 125     def __del__(self):
 126         if self.process:
 127             try:
 128                 self.process.kill()
 129                 self.process.wait()
 130             except OSError:
 131                 pass
 132
 133     def wait(self, *args, **kwargs):
 134         return self.process.wait(*args, **kwargs)
 135
 136 class VcsSim(object):
 137     logname = "simv.log"
 138
 139     def __init__(self, sim_cmd=None, debug=False):
 140         if sim_cmd:
 141             cmd = shlex.split(sim_cmd)
 142         else:
 143             cmd = ["simv"]
 144         cmd += ["+jtag_vpi_enable"]
 145         if debug:
 146             cmd[0] = cmd[0] + "-debug"
 147             cmd += ["+vcdplusfile=output/gdbserver.vpd"]
 148         logfile = open(self.logname, "w")
 149         logfile.write("+ %s\n" % " ".join(cmd))
 150         logfile.flush()
 151         listenfile = open(self.logname, "r")
 152         listenfile.seek(0, 2)
 153         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
 154                 stdout=logfile, stderr=logfile)
 155         done = False
 156         while not done:
 157             # Fail if VCS exits early
 158             exit_code = self.process.poll()
 159             if exit_code is not None:
 160                 raise RuntimeError('VCS simulator exited early with status %d'
 161                                    % exit_code)
 162
 163             line = listenfile.readline()
 164             if not line:
 165                 time.sleep(1)
 166             match = re.match(r"^Listening on port (\d+)$", line)
 167             if match:
 168                 done = True
 169                 self.port = int(match.group(1))
 170                 os.environ['JTAG_VPI_PORT'] = str(self.port)
 171
 172     def __del__(self):
 173         try:
 174             self.process.kill()
 175             self.process.wait()
 176         except OSError:
 177             pass
 178
 179 class Openocd(object):
 180     logfile = tempfile.NamedTemporaryFile(prefix='openocd', suffix='.log')
 181     logname = logfile.name
 182     print "OpenOCD Temporary Log File: %s" % logname
 183
 184     def __init__(self, server_cmd=None, config=None, debug=False, timeout=60):
 185         if server_cmd:
 186             cmd = shlex.split(server_cmd)
 187         else:
 188             openocd = os.path.expandvars("$RISCV/bin/openocd")
 189             cmd = [openocd]
 190             if debug:
 191                 cmd.append("-d")
 192
 193         # This command needs to come before any config scripts on the command
 194         # line, since they are executed in order.
 195         cmd += [
 196             # Tell OpenOCD to bind gdb to an unused, ephemeral port.
 197             "--command",
 198             "gdb_port 0",
 199             # Disable tcl and telnet servers, since they are unused and because
 200             # the port numbers will conflict if multiple OpenOCD processes are
 201             # running on the same server.
 202             "--command",
 203             "tcl_port disabled",
 204             "--command",
 205             "telnet_port disabled",
 206         ]
 207
 208         if config:
 209             f = find_file(config)
 210             if f is None:
 211                 print "Unable to read file " + config
 212                 exit(1)
 213
 214             cmd += ["-f", f]
 215         if debug:
 216             cmd.append("-d")
 217
 218         logfile = open(Openocd.logname, "w")
 219         logfile.write("+ %s\n" % " ".join(cmd))
 220         logfile.flush()
 221         self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
 222                 stdout=logfile, stderr=logfile)
 223
 224         try:
 225             # Wait for OpenOCD to have made it through riscv_examine(). When
 226             # using OpenOCD to communicate with a simulator this may take a
 227             # long time, and gdb will time out when trying to connect if we
 228             # attempt too early.
 229             start = time.time()
 230             messaged = False
 231             while True:
 232                 log = open(Openocd.logname).read()
 233                 m = re.search(r"Listening on port (\d+) for gdb connections",
 234                         log)
 235                 if m:
 236                     self.port = int(m.group(1))
 237                     break
 238
 239                 if not self.process.poll() is None:
 240                     raise Exception(
 241                             "OpenOCD exited before completing riscv_examine()")
 242                 if not messaged and time.time() - start > 1:
 243                     messaged = True
 244                     print "Waiting for OpenOCD to start..."
 245                 if (time.time() - start) > timeout:
 246                     raise Exception("ERROR: Timed out waiting for OpenOCD to "
 247                             "listen for gdb")
 248
 249         except Exception:
 250             header("OpenOCD log")
 251             sys.stdout.write(log)
 252             raise
 253
 254     def __del__(self):
 255         try:
 256             self.process.kill()
 257             self.process.wait()
 258         except (OSError, AttributeError):
 259             pass
 260
 261 class OpenocdCli(object):
 262     def __init__(self, port=4444):
 263         self.child = pexpect.spawn(
 264                 "sh -c 'telnet localhost %d | tee openocd-cli.log'" % port)
 265         self.child.expect("> ")
 266
 267     def command(self, cmd):
 268         self.child.sendline(cmd)
 269         self.child.expect(cmd)
 270         self.child.expect("\n")
 271         self.child.expect("> ")
 272         return self.child.before.strip("\t\r\n \0")
 273
 274     def reg(self, reg=''):
 275         output = self.command("reg %s" % reg)
 276         matches = re.findall(r"(\w+) \(/\d+\): (0x[0-9A-F]+)", output)
 277         values = {r: int(v, 0) for r, v in matches}
 278         if reg:
 279             return values[reg]
 280         return values
 281
 282     def load_image(self, image):
 283         output = self.command("load_image %s" % image)
 284         if 'invalid ELF file, only 32bits files are supported' in output:
 285             raise TestNotApplicable(output)
 286
 287 class CannotAccess(Exception):
 288     def __init__(self, address):
 289         Exception.__init__(self)
 290         self.address = address
 291
 292 Thread = collections.namedtuple('Thread', ('id', 'target_id', 'name',
 293     'frame'))
 294
 295 class Gdb(object):
 296     logfile = tempfile.NamedTemporaryFile(prefix="gdb", suffix=".log")
 297     logname = logfile.name
 298     print "GDB Temporary Log File: %s" % logname
 299
 300     def __init__(self,
 301             cmd=os.path.expandvars("$RISCV/bin/riscv64-unknown-elf-gdb")):
 302         self.child = pexpect.spawn(cmd)
 303         self.child.logfile = open(self.logname, "w")
 304         self.child.logfile.write("+ %s\n" % cmd)
 305         self.wait()
 306         self.command("set confirm off")
 307         self.command("set width 0")
 308         self.command("set height 0")
 309         # Force consistency.
 310         self.command("set print entry-values no")
 311
 312     def select_hart(self, hart):
 313         output = self.command("thread %d" % (hart.index + 1))
 314         assert "Unknown" not in output
 315
 316     def wait(self):
 317         """Wait for prompt."""
 318         self.child.expect(r"\(gdb\)")
 319
 320     def command(self, command, timeout=6000):
 321         self.child.sendline(command)
 322         self.child.expect("\n", timeout=timeout)
 323         self.child.expect(r"\(gdb\)", timeout=timeout)
 324         return self.child.before.strip()
 325
 326     def c(self, wait=True, timeout=-1, async=False):
 327         if async:
 328             async = "&"
 329         else:
 330             async = ""
 331         if wait:
 332             output = self.command("c%s" % async, timeout=timeout)
 333             assert "Continuing" in output
 334             return output
 335         else:
 336             self.child.sendline("c%s" % async)
 337             self.child.expect("Continuing")
 338
 339     def interrupt(self):
 340         self.child.send("\003")
 341         self.child.expect(r"\(gdb\)", timeout=6000)
 342         return self.child.before.strip()
 343
 344     def x(self, address, size='w'):
 345         output = self.command("x/%s %s" % (size, address))
 346         value = int(output.split(':')[1].strip(), 0)
 347         return value
 348
 349     def p_raw(self, obj):
 350         output = self.command("p %s" % obj)
 351         m = re.search("Cannot access memory at address (0x[0-9a-f]+)", output)
 352         if m:
 353             raise CannotAccess(int(m.group(1), 0))
 354         return output.split('=')[-1].strip()
 355
 356     def p(self, obj):
 357         output = self.command("p/x %s" % obj)
 358         m = re.search("Cannot access memory at address (0x[0-9a-f]+)", output)
 359         if m:
 360             raise CannotAccess(int(m.group(1), 0))
 361         value = int(output.split('=')[-1].strip(), 0)
 362         return value
 363
 364     def p_string(self, obj):
 365         output = self.command("p %s" % obj)
 366         value = shlex.split(output.split('=')[-1].strip())[1]
 367         return value
 368
 369     def stepi(self):
 370         output = self.command("stepi", timeout=60)
 371         return output
 372
 373     def load(self):
 374         output = self.command("load", timeout=6000)
 375         assert "failed" not in  output
 376         assert "Transfer rate" in output
 377
 378     def b(self, location):
 379         output = self.command("b %s" % location)
 380         assert "not defined" not in output
 381         assert "Breakpoint" in output
 382         return output
 383
 384     def hbreak(self, location):
 385         output = self.command("hbreak %s" % location)
 386         assert "not defined" not in output
 387         assert "Hardware assisted breakpoint" in output
 388         return output
 389
 390     def threads(self):
 391         output = self.command("info threads")
 392         threads = []
 393         for line in output.splitlines():
 394             m = re.match(
 395                     r"[\s\*]*(\d+)\s*Thread (\d+)\s*\(Name: ([^\)]+)\s*(.*)",
 396                     line)
 397             if m:
 398                 threads.append(Thread(*m.groups()))
 399         if not threads:
 400             threads.append(Thread('1', '1', 'Default', '???'))
 401         return threads
 402
 403     def thread(self, thread):
 404         return self.command("thread %s" % thread.id)
 405
 406 def run_all_tests(module, target, parsed):
 407     if not os.path.exists(parsed.logs):
 408         os.makedirs(parsed.logs)
 409
 410     overall_start = time.time()
 411
 412     global gdb_cmd  # pylint: disable=global-statement
 413     gdb_cmd = parsed.gdb
 414
 415     todo = []
 416     for hart in target.harts:
 417         if parsed.misaval:
 418             hart.misa = int(parsed.misaval, 16)
 419             print "Using $misa from command line: 0x%x" % hart.misa
 420         elif hart.misa:
 421             print "Using $misa from hart definition: 0x%x" % hart.misa
 422         else:
 423             todo.append(("ExamineTarget", ExamineTarget, hart))
 424
 425     for name in dir(module):
 426         definition = getattr(module, name)
 427         if type(definition) == type and hasattr(definition, 'test') and \
 428                 (not parsed.test or any(test in name for test in parsed.test)):
 429             todo.append((name, definition, None))
 430
 431     results, count = run_tests(parsed, target, todo)
 432
 433     header("ran %d tests in %.0fs" % (count, time.time() - overall_start),
 434             dash=':')
 435
 436     return print_results(results)
 437
 438 good_results = set(('pass', 'not_applicable'))
 439 def run_tests(parsed, target, todo):
 440     results = {}
 441     count = 0
 442
 443     for name, definition, hart in todo:
 444         log_name = os.path.join(parsed.logs, "%s-%s-%s.log" %
 445                 (time.strftime("%Y%m%d-%H%M%S"), type(target).__name__, name))
 446         log_fd = open(log_name, 'w')
 447         print "Running %s > %s ..." % (name, log_name),
 448         instance = definition(target, hart)
 449         sys.stdout.flush()
 450         log_fd.write("Test: %s\n" % name)
 451         log_fd.write("Target: %s\n" % type(target).__name__)
 452         start = time.time()
 453         real_stdout = sys.stdout
 454         sys.stdout = log_fd
 455         try:
 456             result = instance.run()
 457             log_fd.write("Result: %s\n" % result)
 458         finally:
 459             sys.stdout = real_stdout
 460             log_fd.write("Time elapsed: %.2fs\n" % (time.time() - start))
 461         print "%s in %.2fs" % (result, time.time() - start)
 462         if result not in good_results and parsed.print_failures:
 463             sys.stdout.write(open(log_name).read())
 464         sys.stdout.flush()
 465         results.setdefault(result, []).append((name, log_name))
 466         count += 1
 467         if result not in good_results and parsed.fail_fast:
 468             break
 469
 470     return results, count
 471
 472 def print_results(results):
 473     result = 0
 474     for key, value in results.iteritems():
 475         print "%d tests returned %s" % (len(value), key)
 476         if key not in good_results:
 477             result = 1
 478             for name, log_name in value:
 479                 print "   %s > %s" % (name, log_name)
 480
 481     return result
 482
 483 def add_test_run_options(parser):
 484     parser.add_argument("--logs", default="logs",
 485             help="Store logs in the specified directory.")
 486     parser.add_argument("--fail-fast", "-f", action="store_true",
 487             help="Exit as soon as any test fails.")
 488     parser.add_argument("--print-failures", action="store_true",
 489             help="When a test fails, print the log file to stdout.")
 490     parser.add_argument("test", nargs='*',
 491             help="Run only tests that are named here.")
 492     parser.add_argument("--gdb",
 493             help="The command to use to start gdb.")
 494     parser.add_argument("--misaval",
 495             help="Don't run ExamineTarget, just assume the misa value which is "
 496             "specified.")
 497
 498 def header(title, dash='-', length=78):
 499     if title:
 500         dashes = dash * (length - 4 - len(title))
 501         before = dashes[:len(dashes)/2]
 502         after = dashes[len(dashes)/2:]
 503         print "%s[ %s ]%s" % (before, title, after)
 504     else:
 505         print dash * length
 506
 507 def print_log(path):
 508     header(path)
 509     lines = open(path, "r").readlines()
 510     for l in lines:
 511         sys.stdout.write(l)
 512     print
 513
 514 class BaseTest(object):
 515     compiled = {}
 516
 517     def __init__(self, target, hart=None):
 518         self.target = target
 519         if hart:
 520             self.hart = hart
 521         else:
 522             self.hart = random.choice(target.harts)
 523         self.server = None
 524         self.target_process = None
 525         self.binary = None
 526         self.start = 0
 527         self.logs = []
 528
 529     def early_applicable(self):
 530         """Return a false value if the test has determined it cannot run
 531         without ever needing to talk to the target or server."""
 532         # pylint: disable=no-self-use
 533         return True
 534
 535     def setup(self):
 536         pass
 537
 538     def compile(self):
 539         compile_args = getattr(self, 'compile_args', None)
 540         if compile_args:
 541             if compile_args not in BaseTest.compiled:
 542                 # pylint: disable=star-args
 543                 BaseTest.compiled[compile_args] = \
 544                         self.hart.compile(*compile_args)
 545         self.binary = BaseTest.compiled.get(compile_args)
 546
 547     def classSetup(self):
 548         self.compile()
 549         self.target_process = self.target.create()
 550         if self.target_process:
 551             self.logs.append(self.target_process.logname)
 552         try:
 553             self.server = self.target.server()
 554             self.logs.append(self.server.logname)
 555         except Exception:
 556             for log in self.logs:
 557                 print_log(log)
 558             raise
 559
 560     def classTeardown(self):
 561         del self.server
 562         del self.target_process
 563
 564     def run(self):
 565         """
 566         If compile_args is set, compile a program and set self.binary.
 567
 568         Call setup().
 569
 570         Then call test() and return the result, displaying relevant information
 571         if an exception is raised.
 572         """
 573
 574         sys.stdout.flush()
 575
 576         if not self.early_applicable():
 577             return "not_applicable"
 578
 579         self.start = time.time()
 580
 581         try:
 582             self.classSetup()
 583             self.setup()
 584             result = self.test()    # pylint: disable=no-member
 585         except TestNotApplicable:
 586             result = "not_applicable"
 587         except Exception as e: # pylint: disable=broad-except
 588             if isinstance(e, TestFailed):
 589                 result = "fail"
 590             else:
 591                 result = "exception"
 592             if isinstance(e, TestFailed):
 593                 header("Message")
 594                 print e.message
 595             header("Traceback")
 596             traceback.print_exc(file=sys.stdout)
 597             return result
 598
 599         finally:
 600             for log in self.logs:
 601                 print_log(log)
 602             header("End of logs")
 603             self.classTeardown()
 604
 605         if not result:
 606             result = 'pass'
 607         return result
 608
 609 gdb_cmd = None
 610 class GdbTest(BaseTest):
 611     def __init__(self, target, hart=None):
 612         BaseTest.__init__(self, target, hart=hart)
 613         self.gdb = None
 614
 615     def classSetup(self):
 616         BaseTest.classSetup(self)
 617
 618         if gdb_cmd:
 619             self.gdb = Gdb(gdb_cmd)
 620         else:
 621             self.gdb = Gdb()
 622
 623         self.logs.append(self.gdb.logname)
 624
 625         if self.binary:
 626             self.gdb.command("file %s" % self.binary)
 627         if self.target:
 628             self.gdb.command("set arch riscv:rv%d" % self.hart.xlen)
 629             self.gdb.command("set remotetimeout %d" % self.target.timeout_sec)
 630         if self.server.port:
 631             self.gdb.command(
 632                     "target extended-remote localhost:%d" % self.server.port)
 633             self.gdb.select_hart(self.hart)
 634
 635         for cmd in self.target.gdb_setup:
 636             self.gdb.command(cmd)
 637
 638         # FIXME: OpenOCD doesn't handle PRIV now
 639         #self.gdb.p("$priv=3")
 640
 641     def classTeardown(self):
 642         del self.gdb
 643         BaseTest.classTeardown(self)
 644
 645 class GdbSingleHartTest(GdbTest):
 646     def classSetup(self):
 647         GdbTest.classSetup(self)
 648
 649         for hart in self.target.harts:
 650             # Park all harts that we're not using in a safe place.
 651             if hart != self.hart:
 652                 self.gdb.select_hart(hart)
 653                 self.gdb.p("$pc=loop_forever")
 654         self.gdb.select_hart(self.hart)
 655
 656 class ExamineTarget(GdbTest):
 657     def test(self):
 658         self.target.misa = self.gdb.p("$misa")
 659
 660         txt = "RV"
 661         if (self.target.misa >> 30) == 1:
 662             txt += "32"
 663         elif (self.target.misa >> 62) == 2:
 664             txt += "64"
 665         elif (self.target.misa >> 126) == 3:
 666             txt += "128"
 667         else:
 668             raise TestFailed("Couldn't determine XLEN from $misa (0x%x)" %
 669                     self.target.misa)
 670
 671         for i in range(26):
 672             if self.target.misa & (1<<i):
 673                 txt += chr(i + ord('A'))
 674         print txt,
 675
 676 class TestFailed(Exception):
 677     def __init__(self, message):
 678         Exception.__init__(self)
 679         self.message = message
 680
 681 class TestNotApplicable(Exception):
 682     def __init__(self, message):
 683         Exception.__init__(self)
 684         self.message = message
 685
 686 def assertEqual(a, b):
 687     if a != b:
 688         raise TestFailed("%r != %r" % (a, b))
 689
 690 def assertNotEqual(a, b):
 691     if a == b:
 692         raise TestFailed("%r == %r" % (a, b))
 693
 694 def assertIn(a, b):
 695     if a not in b:
 696         raise TestFailed("%r not in %r" % (a, b))
 697
 698 def assertNotIn(a, b):
 699     if a in b:
 700         raise TestFailed("%r in %r" % (a, b))
 701
 702 def assertGreater(a, b):
 703     if not a > b:
 704         raise TestFailed("%r not greater than %r" % (a, b))
 705
 706 def assertLess(a, b):
 707     if not a < b:
 708         raise TestFailed("%r not less than %r" % (a, b))
 709
 710 def assertTrue(a):
 711     if not a:
 712         raise TestFailed("%r is not True" % a)
 713
 714 def assertRegexpMatches(text, regexp):
 715     if not re.search(regexp, text):
 716         raise TestFailed("can't find %r in %r" % (regexp, text))