Merge pull request #489 from riscv-software-src/power_dance

debug: Test OpenOCD behavior when harts become unavailable, using new spike mechanism

10 files changed, 196 insertions, 55 deletions

diff --git a/debug/gdbserver.py b/debug/gdbserver.py
index ea3bb0c..97e49d8 100755
--- a/debug/gdbserver.py
+++ b/debug/gdbserver.py
@@ -19,7 +19,8 @@ from testlib import assertGreater, assertRegex, assertLess
 from testlib import GdbTest, GdbSingleHartTest, TestFailed
 from testlib import TestNotApplicable, CompileError
 from testlib import UnknownThread
-from testlib import CouldNotReadRegisters
+from testlib import CouldNotReadRegisters, CommandException
+from testlib import ThreadTerminated
 
 MSTATUS_UIE = 0x00000001
 MSTATUS_SIE = 0x00000002
@@ -1807,22 +1808,29 @@ class EbreakTest(GdbSingleHartTest):
         output = self.gdb.c()
         assertIn("_exit", output)
 
-class CeaseMultiTest(GdbTest):
-    """Test that we work correctly when a hart ceases to respond (e.g. because
+class UnavailableMultiTest(GdbTest):
+    """Test that we work correctly when a hart becomes unavailable (e.g. because
     it's powered down)."""
     compile_args = ("programs/counting_loop.c", "-DDEFINE_MALLOC",
             "-DDEFINE_FREE")
 
     def early_applicable(self):
-        return self.hart.support_cease and len(self.target.harts) > 1
+        return (self.hart.support_cease or
+                self.target.support_unavailable_control) \
+            and len(self.target.harts) > 1
 
     def setup(self):
         ProgramTest.setup(self)
-        self.parkOtherHarts("precease")
+        self.parkOtherHarts()
 
     def test(self):
         # Run all the way to the infinite loop in exit
-        self.gdb.c(wait=False)
+        self.gdb.c_all(wait=False)
+        # Other hart should have become unavailable.
+        if self.target.support_unavailable_control:
+            self.server.wait_until_running(self.target.harts)
+            self.server.command(
+                    f"riscv dmi_write 0x1f 0x{(1<<self.hart.id)&0x3:x}")
         self.gdb.expect(r"\S+ became unavailable.")
         self.gdb.interrupt()
 
@@ -1834,7 +1842,7 @@ class CeaseMultiTest(GdbTest):
                     self.gdb.p("$misa")
                     assert False, \
                         "Shouldn't be able to access unavailable hart."
-                except UnknownThread:
+                except (UnknownThread, CommandException):
                     pass
 
         # Check that the main hart can still be debugged.
@@ -1872,11 +1880,12 @@ class CeaseStepiTest(ProgramTest):
         except CouldNotReadRegisters:
             pass
 
-class CeaseRunTest(ProgramTest):
+class UnavailableRunTest(ProgramTest):
     """Test that we work correctly when the hart we're debugging ceases to
     respond."""
     def early_applicable(self):
-        return self.hart.support_cease
+        return self.hart.support_cease or \
+            self.target.support_unavailable_control
 
     def test(self):
         self.gdb.b("main")
@@ -1884,10 +1893,23 @@ class CeaseRunTest(ProgramTest):
         assertIn("Breakpoint", output)
         assertIn("main", output)
 
-        self.gdb.p("$pc=precease")
+        if self.target.support_unavailable_control:
+            self.gdb.p("$pc=loop_forever")
+        else:
+            self.gdb.p("$pc=cease")
         self.gdb.c(wait=False)
+        if self.target.support_unavailable_control:
+            self.server.wait_until_running([self.hart])
+            self.server.command(
+                    f"riscv dmi_write 0x1f 0x{(~(1<<self.hart.id))&0x3:x}")
         self.gdb.expect(r"\S+ became unavailable.")
         self.gdb.interrupt()
+        # gdb might automatically switch to the available hart.
+        try:
+            self.gdb.select_hart(self.hart)
+        except ThreadTerminated:
+            # GDB sees that the thread is gone. Count this as success.
+            return
         try:
             self.gdb.p("$pc")
             assert False, ("Registers shouldn't be accessible when the hart is "
@@ -1895,6 +1917,33 @@ class CeaseRunTest(ProgramTest):
         except CouldNotReadRegisters:
             pass
 
+class UnavailableCycleTest(ProgramTest):
+    """Test that harts can be debugged after becoming temporarily
+    unavailable."""
+    def early_applicable(self):
+        return self.target.support_unavailable_control
+
+    def test(self):
+        self.gdb.b("main")
+        output = self.gdb.c()
+        assertIn("Breakpoint", output)
+        assertIn("main", output)
+
+        self.gdb.p("$pc=loop_forever")
+        self.gdb.c(wait=False)
+        self.server.wait_until_running([self.hart])
+        self.server.command(
+                f"riscv dmi_write 0x1f 0x{(~(1<<self.hart.id))&0x3:x}")
+        self.gdb.expect(r"\S+ became unavailable.")
+
+        # Now send a DMI command through OpenOCD to make the hart available
+        # again.
+
+        self.server.command("riscv dmi_write 0x1f 0x3")
+        self.gdb.expect(r"\S+ became available")
+        self.gdb.interrupt()
+        self.gdb.p("$pc")
+
 class FreeRtosTest(GdbTest):
     def early_applicable(self):
         return self.target.freertos_binary
@@ -1989,7 +2038,6 @@ class EtriggerTest(DebugTest):
         self.gdb.b("handle_trap")
 
     def test(self):
-        self.gdb.command(f"monitor targets {self.hart.id}")
         # Set trigger on Load access fault
         self.gdb.command("monitor riscv etrigger set m 0x20")
         # Set fox to a null pointer so we'll get a load access exception later.
@@ -2009,7 +2057,6 @@ class IcountTest(DebugTest):
         DebugTest.setup(self)
         self.gdb.b("main")
         self.gdb.c()
-        self.gdb.command(f"monitor targets {self.hart.id}")
 
     def test(self):
         # Execute 2 instructions.
@@ -2039,7 +2086,6 @@ class ItriggerTest(GdbSingleHartTest):
         self.gdb.load()
 
     def test(self):
-        self.gdb.command(f"monitor targets {self.hart.id}")
         output = self.gdb.command("monitor riscv itrigger set 0x80")
         assertIn("Doesn't make sense", output)
         output = self.gdb.command("monitor riscv itrigger set m 0")
diff --git a/debug/targets.py b/debug/targets.py
index 1952749..3f63e79 100644
--- a/debug/targets.py
+++ b/debug/targets.py
@@ -129,6 +129,9 @@ class Target:
     # in https://github.com/FreeRTOS/FreeRTOS.
     freertos_binary = None
 
+    # Supports controlling hart availability through DMCUSTOM.
+    support_unavailable_control = False
+
     # Internal variables:
     directory = None
     temporary_files = []
diff --git a/debug/targets/RISC-V/spike32-2-hwthread.py b/debug/targets/RISC-V/spike32-2-hwthread.py
index 3a24269..b617be2 100644
--- a/debug/targets/RISC-V/spike32-2-hwthread.py
+++ b/debug/targets/RISC-V/spike32-2-hwthread.py
@@ -10,6 +10,7 @@ class spike32_2(targets.Target):
     timeout_sec = 5
     implements_custom_test = True
     support_memory_sampling = False # not supported without sba
+    support_unavailable_control = True
 
     def create(self):
         return testlib.Spike(self, isa="RV32IMAFDV", support_hasel=True,
diff --git a/debug/targets/RISC-V/spike32-2.py b/debug/targets/RISC-V/spike32-2.py
index 6a5a839..1d0cc48 100644
--- a/debug/targets/RISC-V/spike32-2.py
+++ b/debug/targets/RISC-V/spike32-2.py
@@ -9,6 +9,7 @@ class spike32_2(targets.Target):
     openocd_config_path = "spike-2.cfg"
     timeout_sec = 30
     implements_custom_test = True
+    support_unavailable_control = True
 
     def create(self):
         return testlib.Spike(self, isa="RV32IMAFC", progbufsize=0, dmi_rti=4,
diff --git a/debug/targets/RISC-V/spike32.py b/debug/targets/RISC-V/spike32.py
index 0d67ebd..f0afd88 100644
--- a/debug/targets/RISC-V/spike32.py
+++ b/debug/targets/RISC-V/spike32.py
@@ -17,6 +17,7 @@ class spike32(targets.Target):
     implements_custom_test = True
     support_memory_sampling = False # Needs SBA
     freertos_binary = "bin/RTOSDemo32.axf"
+    support_unavailable_control = True
 
     def create(self):
         # 64-bit FPRs on 32-bit target
diff --git a/debug/targets/RISC-V/spike64-2-hwthread.py b/debug/targets/RISC-V/spike64-2-hwthread.py
index 1ac184a..d1d2bf7 100644
--- a/debug/targets/RISC-V/spike64-2-hwthread.py
+++ b/debug/targets/RISC-V/spike64-2-hwthread.py
@@ -13,6 +13,7 @@ class spike64_2(targets.Target):
     implements_custom_test = True
     support_hasel = False
     support_memory_sampling = False # Needs SBA
+    support_unavailable_control = True
 
     def create(self):
         return testlib.Spike(self, isa="RV64IMAFDV", abstract_rti=30,
diff --git a/debug/targets/RISC-V/spike64-2-rtos.py b/debug/targets/RISC-V/spike64-2-rtos.py
index 33c1ff2..f4de8b8 100644
--- a/debug/targets/RISC-V/spike64-2-rtos.py
+++ b/debug/targets/RISC-V/spike64-2-rtos.py
@@ -13,6 +13,7 @@ class spike64_2_rtos(targets.Target):
     test_semihosting = False
     support_manual_hwbp = False # not supported with `-rtos riscv`
     support_memory_sampling = False # not supported with `-rtos riscv`
+    support_unavailable_control = True
 
     def create(self):
         return testlib.Spike(self, abstract_rti=30, support_hasel=False,
diff --git a/debug/targets/RISC-V/spike64-2.py b/debug/targets/RISC-V/spike64-2.py
index 48326ad..e4c7524 100644
--- a/debug/targets/RISC-V/spike64-2.py
+++ b/debug/targets/RISC-V/spike64-2.py
@@ -10,6 +10,7 @@ class spike64_2(targets.Target):
     timeout_sec = 5
     implements_custom_test = True
     support_memory_sampling = False # Needs SBA
+    support_unavailable_control = True
 
     def create(self):
         return testlib.Spike(self)
diff --git a/debug/targets/RISC-V/spike64.py b/debug/targets/RISC-V/spike64.py
index 79176c2..8f5ba4f 100644
--- a/debug/targets/RISC-V/spike64.py
+++ b/debug/targets/RISC-V/spike64.py
@@ -17,6 +17,7 @@ class spike64(targets.Target):
     timeout_sec = 30
     implements_custom_test = True
     freertos_binary = "bin/RTOSDemo64.axf"
+    support_unavailable_control = True
 
     def create(self):
         # 32-bit FPRs only
diff --git a/debug/testlib.py b/debug/testlib.py
index 2155e05..63cc49c 100644
--- a/debug/testlib.py
+++ b/debug/testlib.py
@@ -1,7 +1,6 @@
 import collections
 import os
 import os.path
-import random
 import re
 import shlex
 import subprocess
@@ -294,6 +293,7 @@ class VcsSim:
             pass
 
 class Openocd:
+    # pylint: disable=too-many-instance-attributes
     # pylint: disable-next=consider-using-with
     logfile = tempfile.NamedTemporaryFile(prefix='openocd', suffix='.log')
     logname = logfile.name
@@ -302,6 +302,7 @@ class Openocd:
                  freertos=False, debug_openocd=False):
         self.timeout = timeout
         self.debug_openocd = debug_openocd
+        self.command_count = 0
 
         if server_cmd:
             cmd = shlex.split(server_cmd)
@@ -314,15 +315,13 @@ class Openocd:
         # line, since they are executed in order.
         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",
+            "--command", "gdb_port 0",
+            # We don't use the TCL server.
+            "--command", "tcl_port disabled",
+            # Put the regular command prompt in stdin. Don't listen on a port
+            # because it will conflict if multiple OpenOCD instances are running
+            # at the same time.
+            "--command", "telnet_port pipe",
         ]
 
         if config:
@@ -343,6 +342,9 @@ class Openocd:
 
         # pylint: disable-next=consider-using-with
         raw_logfile = open(Openocd.logname, "wb")
+        # pylint: disable-next=consider-using-with
+        self.read_log_fd = open(Openocd.logname, "rb")
+        self.log_buf = b""
         try:
             # pylint: disable-next=consider-using-with
             spike_dasm = subprocess.Popen("spike-dasm", stdin=subprocess.PIPE,
@@ -364,12 +366,12 @@ class Openocd:
         logfile.flush()
 
         self.gdb_ports = []
-        self.process = self.start(cmd, logfile, extra_env)
+        self.start(cmd, logfile, extra_env)
 
     def start(self, cmd, logfile, extra_env):
         combined_env = {**os.environ, **extra_env}
         # pylint: disable-next=consider-using-with
-        process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
+        self.process = subprocess.Popen(cmd, stdin=subprocess.PIPE,
                 stdout=logfile, stderr=logfile, env=combined_env)
 
         try:
@@ -377,38 +379,21 @@ class Openocd:
             # using OpenOCD to communicate with a simulator this may take a
             # long time, and gdb will time out when trying to connect if we
             # attempt too early.
-            start = time.time()
-            messaged = False
-            with open(Openocd.logname, "r", encoding='utf-8') as fd:
-                while True:
-                    line = fd.readline()
-                    if not line:
-                        if not process.poll() is None:
-                            raise TestLibError("OpenOCD exited early.")
-                        time.sleep(0.1)
-                        continue
-
-                    m = re.search(
-                        r"Listening on port (\d+) for gdb connections", line)
-                    if m:
-                        self.gdb_ports.append(int(m.group(1)))
-
-                    if "telnet server disabled" in line:
-                        break
-
-                    if not messaged and time.time() - start > 1:
-                        messaged = True
-                        print("Waiting for OpenOCD to start...")
-                    if (time.time() - start) > self.timeout:
-                        raise TestLibError("Timed out waiting for OpenOCD to "
-                                "listen for gdb")
+
+            while True:
+                m = self.expect(
+                        rb"(Listening on port (\d+) for gdb connections|"
+                        rb"tcl server disabled)",
+                        message="Waiting for OpenOCD to start up...")
+                if b"gdb" in m.group(1):
+                    self.gdb_ports.append(int(m.group(2)))
+                else:
+                    break
 
             if self.debug_openocd:
                 # pylint: disable=consider-using-with
                 self.debugger = subprocess.Popen(["gnome-terminal", "-e",
-                                                  f"gdb --pid={process.pid}"])
-            return process
-
+                                            f"gdb --pid={self.process.pid}"])
         except Exception:
             print_log(Openocd.logname)
             raise
@@ -434,6 +419,83 @@ class Openocd:
                     return True
         return False
 
+    def command(self, cmd):
+        """Write the command to OpenOCD's stdin. Return the output of the
+        command, minus the prompt."""
+        self.process.stdin.write(f"{cmd}\n".encode())
+        self.process.stdin.flush()
+        m = self.expect(re.escape(f"{cmd}\n".encode()))
+
+        # The prompt isn't flushed to the log, so send a unique command that
+        # lets us find where output of the last command ends.
+        magic = f"# {self.command_count}x".encode()
+        self.command_count += 1
+        self.process.stdin.write(magic + b"\n")
+        self.process.stdin.flush()
+        m = self.expect(rb"(.*)^> " + re.escape(magic))
+        return m.group(1)
+
+    def expect(self, regex, message=None):
+        """Wait for the regex to match the log, and return the match object. If
+        message is given, print it while waiting.
+        We read the logfile to tell us what OpenOCD has done."""
+        messaged = False
+        start = time.time()
+
+        while True:
+            for line in self.read_log_fd.readlines():
+                line = line.rstrip()
+                # Remove nulls, carriage returns, and newlines.
+                line = re.sub(rb"[\x00\r\n]+", b"", line)
+                # Remove debug messages.
+                debug_match = re.search(rb"Debug: \d+ \d+ .*", line)
+                if debug_match:
+                    line = line[:debug_match.start()] + line[debug_match.end():]
+                    self.log_buf += line
+                else:
+                    self.log_buf += line + b"\n"
+
+            m = re.search(regex, self.log_buf, re.MULTILINE | re.DOTALL)
+            if m:
+                self.log_buf = self.log_buf[m.end():]
+                return m
+
+            if not self.process.poll() is None:
+                raise TestLibError("OpenOCD exited early.")
+
+            if message and not messaged and time.time() - start > 1:
+                messaged = True
+                print(message)
+
+            if (time.time() - start) > self.timeout:
+                raise TestLibError(f"Timed out waiting for {regex} in "
+                                   f"{Openocd.logname}")
+
+            time.sleep(0.1)
+
+    def targets(self):
+        """Run `targets` command."""
+        result = self.command("targets").decode()
+        #     TargetName         Type       Endian TapName            State
+        # --  ------------------ ---------- ------ ------------------ --------
+        #  0* riscv.cpu          riscv      little riscv.cpu          halted
+        lines = result.splitlines()
+        headers = lines[0].split()
+        data = []
+        for line in lines[2:]:
+            data.append(dict(zip(headers, line.split()[1:])))
+        return data
+
+    def wait_until_running(self, harts):
+        """Wait until the given harts are running."""
+        start = time.time()
+        while True:
+            targets = self.targets()
+            if all(targets[hart.id]["State"] == "running" for hart in harts):
+                return
+            if time.time() - start > self.timeout:
+                raise TestLibError("Timed out waiting for targets to run.")
+
 class OpenocdCli:
     def __init__(self, port=4444):
         self.child = pexpect.spawn(
@@ -493,6 +555,9 @@ class UnknownThread(Exception):
     def __init__(self, explanation):
         Exception.__init__(self, explanation)
 
+class ThreadTerminated(Exception):
+    pass
+
 Thread = collections.namedtuple('Thread', ('id', 'description', 'target_id',
     'name', 'frame'))
 
@@ -590,6 +655,15 @@ def parse_rhs(text):
         raise TestLibError(f"Unexpected input: {tokens!r}")
     return result
 
+class CommandException(Exception):
+    pass
+
+class CommandSendTimeout(CommandException):
+    pass
+
+class CommandCompleteTimeout(CommandException):
+    pass
+
 class Gdb:
     """A single gdb class which can interact with one or more gdb instances."""
 
@@ -691,6 +765,8 @@ class Gdb:
             output = self.command(f"thread {h['thread'].id}", ops=5)
             if "Unknown" in output:
                 raise UnknownThread(output)
+            if f"Thread ID {h['thread'].id} has terminated" in output:
+                raise ThreadTerminated(output)
 
     def push_state(self):
         self.stack.append({
@@ -718,8 +794,14 @@ class Gdb:
                     reset_delays=None)
         timeout = max(1, ops) * self.timeout
         self.active_child.sendline(command)
-        self.active_child.expect("\n", timeout=timeout)
-        self.active_child.expect(r"\(gdb\)", timeout=timeout)
+        try:
+            self.active_child.expect("\n", timeout=timeout)
+        except pexpect.exceptions.TIMEOUT as exc:
+            raise CommandSendTimeout(command) from exc
+        try:
+            self.active_child.expect(r"\(gdb\)", timeout=timeout)
+        except pexpect.exceptions.TIMEOUT as exc:
+            raise CommandCompleteTimeout(command) from exc
         output = self.active_child.before.decode("utf-8", errors="ignore")
         ansi_escape = re.compile(r'\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*[@-~])')
         return ansi_escape.sub('', output).strip()
@@ -1136,7 +1218,9 @@ class BaseTest:
         if hart:
             self.hart = hart
         else:
+            import random   # pylint: disable=import-outside-toplevel
             self.hart = random.choice(target.harts)
+            #self.hart = target.harts[-1]
         self.server = None
         self.target_process = None
         self.binary = None
@@ -1308,6 +1392,7 @@ class GdbTest(BaseTest):
                     self.gdb.p(f"$pc={symbol}")
 
         self.gdb.select_hart(self.hart)
+        self.gdb.command(f"monitor targets {self.hart.id}")
 
     def disable_pmp(self):
         # Disable physical memory protection by allowing U mode access to all