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