whitequark · Nov 19, 2018 · Nov 19, 2018 · Nov 19, 2018
Showing with 76 additions and 46 deletions.

+46 −42 software/glasgow/applet/jtag/__init__.py

+1 −1 software/glasgow/applet/jtag/arc.py

+29 −3 software/glasgow/cli.py
diff --git a/software/glasgow/applet/jtag/__init__.py b/software/glasgow/applet/jtag/__init__.py
@@ -206,49 +206,52 @@ def __init__(self, interface, logger):
         self._state      = "Unknown"
         self._current_ir = None
 
-    def _log(self, message, *args):
-        self._logger.log(self._level, "JTAG: " + message, *args)
+    def _log_l(self, message, *args):
+        self._logger.log(self._level, "JTAG-L: " + message, *args)
+
+    def _log_h(self, message, *args):
+        self._logger.log(self._level, "JTAG-H: " + message, *args)
 
     # Low-level operations
 
     async def set_trst(self, state):
         if state is None:
-            self._log("set trst=z")
+            self._log_l("set trst=z")
             await self.lower.write(struct.pack("<B",
                 CMD_TRST|0b01))
         else:
             state = state & 1
-            self._log("set trst=%d", state)
+            self._log_l("set trst=%d", state)
             await self.lower.write(struct.pack("<B",
                 CMD_TRST|(state << 1)))
 
     async def pulse_trst(self):
-        self._log("pulse trst")
+        self._log_l("pulse trst")
         await self.lower.write(struct.pack("<B",
             CMD_RESET))
         self._current_ir = None
 
     async def shift_tms(self, tms_bits):
         tms_bits = bitarray(tms_bits, endian="little")
-        self._log("shift tms=<%s>", tms_bits.to01())
+        self._log_l("shift tms=<%s>", tms_bits.to01())
         await self.lower.write(struct.pack("<BH",
             CMD_SHIFT_TMS|BIT_DATA_OUT, len(tms_bits)))
         await self.lower.write(tms_bits.tobytes())
 
     def _shift_last(self, last):
         if last:
             if self._state == "Shift-IR":
-                self._log("state Shift-IR → Exit1-IR")
+                self._log_l("state Shift-IR → Exit1-IR")
                 self._state = "Exit1-IR"
             elif self._state == "Shift-DR":
-                self._log("state Shift-DR → Exit1-DR")
+                self._log_l("state Shift-DR → Exit1-DR")
                 self._state = "Exit1-DR"
 
     async def shift_tdio(self, tdi_bits, last=True):
         assert self._state in ("Shift-IR", "Shift-DR")
         tdi_bits = bitarray(tdi_bits, endian="little")
         tdo_bits = bitarray(endian="little")
-        self._log("shift tdio-i=<%s>", tdi_bits.to01())
+        self._log_l("shift tdio-i=<%s>", tdi_bits.to01())
         await self.lower.write(struct.pack("<BH",
             CMD_SHIFT_TDIO|BIT_DATA_IN|BIT_DATA_OUT|(BIT_LAST if last else 0),
             len(tdi_bits)))
@@ -257,14 +260,14 @@ async def shift_tdio(self, tdi_bits, last=True):
         tdo_bytes = await self.lower.read(len(tdi_bytes))
         tdo_bits.frombytes(bytes(tdo_bytes))
         while len(tdo_bits) > len(tdi_bits): tdo_bits.pop()
-        self._log("shift tdio-o=<%s>", tdo_bits.to01())
+        self._log_l("shift tdio-o=<%s>", tdo_bits.to01())
         self._shift_last(last)
         return tdo_bits
 
     async def shift_tdi(self, tdi_bits, last=True):
         assert self._state in ("Shift-IR", "Shift-DR")
         tdi_bits = bitarray(tdi_bits, endian="little")
-        self._log("shift tdi=<%s>", tdi_bits.to01())
+        self._log_l("shift tdi=<%s>", tdi_bits.to01())
         await self.lower.write(struct.pack("<BH",
             CMD_SHIFT_TDIO|BIT_DATA_OUT|(BIT_LAST if last else 0),
             len(tdi_bits)))
@@ -281,13 +284,13 @@ async def shift_tdo(self, count, last=True):
         tdo_bytes = await self.lower.read((count + 7) // 8)
         tdo_bits.frombytes(bytes(tdo_bytes))
         while len(tdo_bits) > count: tdo_bits.pop()
-        self._log("shift tdo=<%s>", tdo_bits.to01())
+        self._log_l("shift tdo=<%s>", tdo_bits.to01())
         self._shift_last(last)
         return tdo_bits
 
     async def pulse_tck(self, count):
         assert self._state in ("Run-Test/Idle", "Shift-IR", "Shift-DR", "Pause-IR", "Pause-DR")
-        self._log("pulse tck count=%d", count)
+        self._log_l("pulse tck count=%d", count)
         while count > 0xffff:
             await self.lower.write(struct.pack("<BH",
                 CMD_SHIFT_TDIO, 0xffff))
@@ -299,9 +302,9 @@ async def pulse_tck(self, count):
 
     async def enter_test_logic_reset(self, force=True):
         if force:
-            self._log("state * → Test-Logic-Reset")
+            self._log_l("state * → Test-Logic-Reset")
         elif self._state != "Test-Logic-Reset":
-            self._log("state %s → Test-Logic-Reset", self._state)
+            self._log_l("state %s → Test-Logic-Reset", self._state)
         else:
             return
 
@@ -311,7 +314,7 @@ async def enter_test_logic_reset(self, force=True):
     async def enter_run_test_idle(self):
         if self._state == "Run-Test/Idle": return
 
-        self._log("state %s → Run-Test/Idle", self._state)
+        self._log_l("state %s → Run-Test/Idle", self._state)
         if self._state == "Test-Logic-Reset":
             await self.shift_tms("0")
         elif self._state in ("Exit1-IR", "Exit1-DR"):
@@ -325,7 +328,7 @@ async def enter_run_test_idle(self):
     async def enter_shift_ir(self):
         if self._state == "Shift-IR": return
 
-        self._log("state %s → Shift-IR", self._state)
+        self._log_l("state %s → Shift-IR", self._state)
         if self._state == "Test-Logic-Reset":
             await self.shift_tms("01100")
         elif self._state == "Run-Test/Idle":
@@ -337,7 +340,7 @@ async def enter_shift_ir(self):
     async def enter_pause_ir(self):
         if self._state == "Pause-IR": return
 
-        self._log("state %s → Pause-IR", self._state)
+        self._log_l("state %s → Pause-IR", self._state)
         if self._state == "Exit1-IR":
             await self.shift_tms("0")
         else:
@@ -347,7 +350,7 @@ async def enter_pause_ir(self):
     async def enter_shift_dr(self):
         if self._state == "Shift-DR": return
 
-        self._log("state %s → Shift-DR", self._state)
+        self._log_l("state %s → Shift-DR", self._state)
         if self._state == "Test-Logic-Reset":
             await self.shift_tms("0100")
         elif self._state == "Run-Test/Idle":
@@ -359,7 +362,7 @@ async def enter_shift_dr(self):
     async def enter_pause_dr(self):
         if self._state == "Pause-DR": return
 
-        self._log("state %s → Pause-DR", self._state)
+        self._log_l("state %s → Pause-DR", self._state)
         if self._state == "Exit1-DR":
             await self.shift_tms("0")
         else:
@@ -369,51 +372,51 @@ async def enter_pause_dr(self):
     # High-level register manipulation
 
     async def test_reset(self):
-        self._log("test reset")
+        self._log_h("test reset")
         await self.enter_test_logic_reset()
         await self.enter_run_test_idle()
         self._current_ir = None
 
     async def run_test_idle(self, count):
-        self._log("run-test/idle count=%d", count)
+        self._log_h("run-test/idle count=%d", count)
         await self.enter_run_test_idle()
         await self.pulse_tck(count)
 
     async def write_ir(self, data):
         if data == self._current_ir:
-            self._log("write ir (elided)")
+            self._log_h("write ir (elided)")
             return
         else:
             self._current_ir = bitarray(data, endian="little")
 
-        self._log("write ir")
+        self._log_h("write ir=<%s>", data.to01())
         await self.enter_shift_ir()
         await self.shift_tdi(data)
         await self.enter_run_test_idle()
 
     async def exchange_dr(self, data):
-        self._log("exchange dr")
+        self._log_h("exchange dr")
         await self.enter_shift_dr()
         data = await self.shift_tdio(data)
         await self.enter_run_test_idle()
         return data
 
     async def read_dr(self, count, idempotent=False):
-        if idempotent:
-            self._log("read dr idempotent")
-        else:
-            self._log("read dr")
         await self.enter_shift_dr()
         data = await self.shift_tdo(count, last=not idempotent)
         if idempotent:
             # Shift what we just read back in. This is useful to avoid disturbing any bits
             # in R/W DRs when we go through Update-DR.
             await self.shift_tdi(data)
         await self.enter_run_test_idle()
+        if idempotent:
+            self._log_h("read idempotent dr=<%s>", data.to01())
+        else:
+            self._log_h("read dr=<%s>", data.to01())
         return data
 
     async def write_dr(self, data):
-        self._log("write dr")
+        self._log_h("write dr=<%s>", data.to01())
         await self.enter_shift_dr()
         await self.shift_tdi(data)
         await self.enter_run_test_idle()
@@ -423,7 +426,7 @@ async def write_dr(self, data):
     async def scan_idcode(self, max_idcodes=8):
         await self.test_reset()
 
-        self._log("scan idcode")
+        self._log_h("scan idcode")
         await self.enter_shift_dr()
 
         try:
@@ -433,20 +436,20 @@ async def scan_idcode(self, max_idcodes=8):
                 while len(idcodes) < max_idcodes:
                     first_bit = await self.shift_tdo(1, last=False)
                     if first_bit[0]:
-                        self._log("found idcode")
                         break # IDCODE
                     else:
-                        self._log("found bypass")
+                        self._log_h("found bypass")
                         idcodes.append(None)
                         pass  # BYPASS
                 else:
-                    self._log("too many idcodes")
+                    self._log_h("too many idcodes")
                     return
 
                 idcode_bits = first_bit + await self.shift_tdo(31, last=False)
                 idcode, = struct.unpack("<L", idcode_bits.tobytes())
                 if idcode == 0xffffffff:
                     break
+                self._log_h("found idcode=<%08x>", idcode)
                 idcodes.append(idcode)
 
             return idcodes
@@ -457,13 +460,13 @@ async def scan_idcode(self, max_idcodes=8):
     async def scan_ir(self, count=None, max_length=128):
         await self.test_reset()
 
-        self._log("scan ir")
+        self._log_h("scan ir")
         await self.enter_shift_ir()
 
         try:
             ir_0, = await self.shift_tdo(1, last=False)
             if not ir_0:
-                self._log("invalid ir[0]")
+                self._log_h("invalid ir[0]")
                 return
 
             irs = []
@@ -480,14 +483,15 @@ async def scan_ir(self, count=None, max_length=128):
                         break
                     ir_length += 1
                 else:
-                    self._log("overlong ir")
+                    self._log_h("overlong ir")
                     return
 
+                self._log_h("found ir[%d]", ir_length)
                 irs.append((ir_offset, ir_length))
                 ir_offset += ir_length
 
             if count is not None and len(irs) != count:
-                self._log("ir count does not match idcode count")
+                self._log_h("ir count does not match idcode count")
                 return
 
             return irs
@@ -496,7 +500,7 @@ async def scan_ir(self, count=None, max_length=128):
             await self.enter_run_test_idle()
 
     async def scan_dr_length(self, max_length, zero_ok=False):
-        self._log("scan dr length")
+        self._log_h("scan dr length")
 
         try:
             await self.enter_shift_dr()
@@ -511,15 +515,15 @@ async def scan_dr_length(self, max_length, zero_ok=False):
                     break
                 length += 1
             else:
-                self._log("overlong dr")
+                self._log_h("overlong dr")
                 return
 
             # Restore the old contents, just in case this matters.
             await self.shift_tdi(data[:length], last=True)
 
             if not zero_ok:
                 assert length > 0
-            self._log("scan dr length=%d", length)
+            self._log_h("scan dr length=%d", length)
             return length
 
         finally:
@@ -535,7 +539,7 @@ async def select_tap(self, tap):
             return
 
         if tap >= len(irs):
-            self._log("tap %d not present on chain")
+            self._log_h("tap %d not present on chain")
             return
 
         ir_offset, ir_length = irs[tap]

diff --git a/software/glasgow/applet/jtag/arc.py b/software/glasgow/applet/jtag/arc.py
@@ -42,7 +42,7 @@ async def _wait_txn(self):
             status = DR_STATUS.from_bitarray(status_bits)
             self._log("status %s", status.bits_repr())
             if status.FL:
-                raise GlasgowAppletError("transaction failed")
+                raise GlasgowAppletError("transaction failed: %s" % status.bits_repr())
 
     async def read(self, address, space):
         if space == "memory":

diff --git a/software/glasgow/cli.py b/software/glasgow/cli.py
@@ -60,6 +60,9 @@ def create_argparser():
     parser.add_argument(
         "-q", "--quiet", default=0, action="count",
         help="decrease logging verbosity")
+    parser.add_argument(
+        "-F", "--filter-log", metavar="FILTER", type=str, action="append",
+        help="enable maximum verbosity for log messages starting with 'FILTER: '")
 
     return parser
 
@@ -305,17 +308,40 @@ def format(self, record):
         return "{}{}\033[0m".format(color, super().format(record))
 
 
+class SubjectFilter:
+    def __init__(self, level, subjects):
+        self.level    = level
+        self.subjects = subjects
+
+    def filter(self, record):
+        levelno = record.levelno
+        for subject in self.subjects:
+            if record.msg.startswith(subject + ": "):
+                levelno = logging.DEBUG
+        return levelno >= self.level
+
+
 def create_logger(args):
-    root_logger = logging.getLogger()
-    root_logger.setLevel(logging.INFO + args.quiet * 10 - args.verbose * 10)
-    handler = logging.StreamHandler()
     formatter_args = {"fmt": "{levelname[0]:s}: {name:s}: {message:s}", "style": "{"}
+    handler = logging.StreamHandler()
     if sys.stderr.isatty() and sys.platform != 'win32':
         handler.setFormatter(ANSIColorFormatter(**formatter_args))
     else:
         handler.setFormatter(logging.Formatter(**formatter_args))
+
+    root_logger = logging.getLogger()
     root_logger.addHandler(handler)
 
+    level = logging.INFO + args.quiet * 10 - args.verbose * 10
+    if args.filter_log:
+        handler.addFilter(SubjectFilter(level, args.filter_log))
+        root_logger.setLevel(logging.TRACE)
+    else:
+        # By setting the log level on the root logger, we avoid creating LogRecords in the first
+        # place instead of filtering them later; we have a *lot* of logging, so this is much
+        # more efficient.
+        root_logger.setLevel(level)
+
 
 async def _main():
     args = get_argparser().parse_args()