runner, harness: add logging support and debug output

2 files changed, 14 insertions, 2 deletions

diff --git a/lib/harness.py b/lib/harness.py
index 163bc2b..92ae7fb 100644
--- a/lib/harness.py
+++ b/lib/harness.py
@@ -3,9 +3,12 @@ Harnesses for various types of benchmark logs.
 
 tbd
 """
+import logging
 import re
 from .pubcode import Code128
 
+logger = logging.getLogger(__name__)
+
 
 class TransitionHarness:
     """
@@ -232,7 +235,7 @@ class TransitionHarness:
 
     # Here Be Dragons
     def parser_cb(self, line):
-        # print('[HARNESS] got line {}'.format(line))
+        logger.debug(f"Received: {line}")
         if re.match(r"\[PTA\] benchmark stop", line):
             self.repetitions += 1
             self.synced = False
@@ -499,7 +502,7 @@ class OnboardTimerHarness(TransitionHarness):
 
     # Here Be Dragons
     def parser_cb(self, line):
-        # print('[HARNESS] got line {}'.format(line))
+        logger.debug(f"Received: {line}")
         res = re.match(r"\[PTA\] nop=(\S+)/(\S+)", line)
         if res:
             self.nop_cycles = int(res.group(1))
diff --git a/lib/runner.py b/lib/runner.py
index ebb2fb2..34498ac 100644
--- a/lib/runner.py
+++ b/lib/runner.py
@@ -10,6 +10,7 @@ Functions:
     get_counter_limits -- return arch-specific multipass counter limits (max value, max overflow)
 """
 import json
+import logging
 import os
 import re
 import serial
@@ -19,6 +20,8 @@ import sys
 import time
 from dfatool.lennart.SigrokCLIInterface import SigrokCLIInterface
 
+logger = logging.getLogger(__name__)
+
 
 class SerialReader(serial.threaded.Protocol):
     """
@@ -101,6 +104,7 @@ class SerialMonitor:
         self.ser.parity = "N"
         self.ser.rtscts = False
         self.ser.xonxoff = False
+        logger.debug(f"Opening serial port {port} with {baud}N1")
 
         try:
             self.ser.open()
@@ -234,6 +238,7 @@ class MIMOSAMonitor(SerialMonitor):
     def _mimosactl(self, subcommand):
         cmd = ["mimosactl"]
         cmd.append(subcommand)
+        logger.debug(f"Executing {cmd}")
         res = subprocess.run(cmd)
         if res.returncode != 0:
             res = subprocess.run(cmd)
@@ -350,6 +355,7 @@ class Arch:
         command = ["make", "arch={}".format(self.name), "app={}".format(app), "clean"]
         command.extend(self.opts)
         command.extend(opts)
+        logger.debug(f"Building: {' '.join(command)}")
         res = subprocess.run(
             command,
             stdout=subprocess.PIPE,
@@ -363,6 +369,7 @@ class Arch:
         command = ["make", "-B", "arch={}".format(self.name), "app={}".format(app)]
         command.extend(self.opts)
         command.extend(opts)
+        logger.debug(f"Building: {' '.join(command)}")
         res = subprocess.run(
             command,
             stdout=subprocess.PIPE,
@@ -379,6 +386,7 @@ class Arch:
         command = ["make", "arch={}".format(self.name), "app={}".format(app), "program"]
         command.extend(self.opts)
         command.extend(opts)
+        logger.debug(f"Flashing: {' '.join(command)}")
         res = subprocess.run(
             command,
             stdout=subprocess.PIPE,
@@ -398,6 +406,7 @@ class Arch:
         command = ["make", "arch={}".format(self.name), "info"]
         command.extend(self.opts)
         command.extend(opts)
+        logger.debug(f"Getting Info: {' '.join(command)}")
         res = subprocess.run(
             command,
             stdout=subprocess.PIPE,