runner, harness: add logging support and debug output

3 files changed, 23 insertions, 2 deletions

diff --git a/bin/generate-dfa-benchmark.py b/bin/generate-dfa-benchmark.py
index 98c3602..50f5e58 100755
--- a/bin/generate-dfa-benchmark.py
+++ b/bin/generate-dfa-benchmark.py
@@ -85,6 +85,7 @@ Perform timing measurements of BME680 funtion calls:
 
 import getopt
 import json
+import logging
 import os
 import re
 import sys
@@ -434,6 +435,7 @@ if __name__ == "__main__":
             "dummy= "
             "energytrace= "
             "instance= "
+            "log-level= "
             "mimosa= "
             "repeat= "
             "run= "
@@ -475,6 +477,13 @@ if __name__ == "__main__":
         else:
             opt["trace-filter"] = None
 
+        if "log-level" in opt:
+            numeric_level = getattr(logging, opt["log-level"].upper(), None)
+            if not isinstance(numeric_level, int):
+                print(f"Invalid log level: {args.log_level}", file=sys.stderr)
+                sys.exit(1)
+            logging.basicConfig(level=numeric_level)
+
         if "mimosa" in opt:
             if opt["mimosa"] == "":
                 opt["mimosa"] = dict()
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,