generalize the powermon stuff to become structured logging

.vscode/settings.json

@@ -1,6 +1,9 @@
 {
     "cSpell.words": [
+        "bitmask",
+        "boardid",
         "Meshtastic",
+        "powermon",
         "TORADIO",
         "Vids"
     ],

meshtastic/__main__.py

@@ -22,7 +22,7 @@ from meshtastic.version import get_active_version
 from meshtastic.ble_interface import BLEInterface
 from meshtastic.mesh_interface import MeshInterface
 from meshtastic.powermon import RidenPowerSupply
-from meshtastic.slog.power_mon import PowerMonClient
+from meshtastic.slog import StructuredLogger
 
 def onReceive(packet, interface):
     """Callback invoked when a packet arrives"""
@@ -1087,21 +1087,24 @@ def common():
                             f"Error connecting to localhost:{ex}", 1
                         )
 
-
             # We assume client is fully connected now
             onConnected(client)
 
+            meter = None # assume no power meter
             if args.power_riden:
                 meter = RidenPowerSupply(args.power_riden)
-                PowerMonClient(meter, client)
 
+            StructuredLogger(client, meter)
 
             have_tunnel = platform.system() == "Linux"
             if (
                 args.noproto or args.reply or (have_tunnel and args.tunnel) or args.listen
             ):  # loop until someone presses ctrlc
-                while True:
-                    time.sleep(1000)
+                try:
+                    while True:
+                        time.sleep(1000)
+                except KeyboardInterrupt:
+                    logging.info("Exiting due to keyboard interrupt")
 
         # don't call exit, background threads might be running still
         # sys.exit(0)

meshtastic/powermon/riden.py

@@ -1,7 +1,7 @@
 """code logging power consumption of meshtastic devices."""
 
 import logging
-
+import math
 from datetime import datetime
 
 from riden import Riden
@@ -9,8 +9,27 @@ from riden import Riden
 class PowerMeter:
     """Abstract class for power meters."""
 
-    def getWattHour(self) -> float:
-        """Get the current watt-hour reading."""
+    def __init__(self):
+        """Initialize the PowerMeter object."""
+        self.prevPowerTime = datetime.now()
+        self.prevWattHour = self._getRawWattHour()
+
+    def getWatts(self) -> float:
+        """Get the total amount of power that has been consumed since the previous call of this method"""
+        now = datetime.now()
+        nowWattHour = self._getRawWattHour()
+        watts = (
+            (nowWattHour - self.prevWattHour)
+            / (now - self.prevPowerTime).total_seconds()
+            * 3600
+        )
+        self.prevPowerTime = now
+        self.prevWattHour = nowWattHour
+        return watts
+
+    def _getRawWattHour(self) -> float:
+        """Get the current watt-hour reading (without any offset correction)."""
+        return math.nan
 
 
 
@@ -33,7 +52,6 @@ class RidenPowerSupply(PowerSupply):
     def __init__(self, portName: str = "/dev/ttyUSB0"):
         """Initialize the RidenPowerSupply object.
 
-        Args:
             portName (str, optional): The port name of the power supply. Defaults to "/dev/ttyUSB0".
         """
         self.r = r = Riden(port=portName, baudrate=115200, address=1)
@@ -41,6 +59,7 @@ class RidenPowerSupply(PowerSupply):
             f"Connected to Riden power supply: model {r.type}, sn {r.sn}, firmware {r.fw}. Date/time updated."
         )
         r.set_date_time(datetime.now())
+        super().__init__() # we call this late so that the port is already open and _getRawWattHour callback works
 
     def setMaxCurrent(self, i: float):
         """Set the maximum current the supply will provide."""
@@ -51,7 +70,7 @@ class RidenPowerSupply(PowerSupply):
         self.r.set_v_set(v)  # my WM1110 devboard header is directly connected to the 3.3V rail
         self.r.set_output(1)
 
-    def getWattHour(self) -> float:
+    def _getRawWattHour(self) -> float:
         """Get the current watt-hour reading."""
         self.r.update()
         return self.r.wh

meshtastic/slog/__init__.py

@@ -0,0 +1,3 @@
+"""Structured logging framework (see dev docs for more info)"""
+
+from .slog import StructuredLogger

meshtastic/slog/power_mon.py

@@ -1,97 +0,0 @@
-"""code logging power consumption of meshtastic devices."""
-
-import logging
-import re
-import atexit
-from datetime import datetime
-
-import pandas as pd
-
-from meshtastic.mesh_interface import MeshInterface
-from meshtastic.observable import Event
-from meshtastic.powermon import PowerSupply
-
-logRegex = re.compile(".*S:PM:0x([0-9A-Fa-f]+),(.*)")
-
-
-class PowerMonClient:
-    """Client for monitoring power consumption of meshtastic devices."""
-
-    def __init__(self, power: PowerSupply, client: MeshInterface) -> None:
-        """Initialize the PowerMonClient object.
-
-        Args:
-            power (PowerSupply): The power supply object.
-            client (MeshInterface): The MeshInterface object to monitor.
-        """
-        self.client = client
-        self.state = 0  # The current power mon state bitfields
-        self.columns = ["time", "power", "reason", "bitmask"]
-        self.rawData = pd.DataFrame(columns=self.columns)  # use time as the index
-
-        # for efficiency reasons we keep new data in a list - only adding to rawData when needed
-        self.newData: list[dict] = []
-
-        self.power = power
-        power.setMaxCurrent(0.300) # Set current limit to 300mA - hopefully enough to power any board but not break things if there is a short circuit
-        power.powerOn(3.3)
-
-        # Used to calculate watts over an interval
-        self.prevPowerTime = datetime.now()
-        self.prevWattHour = power.getWattHour()
-        atexit.register(self._exitHandler)
-        client.onLogMessage.subscribe(self._onLogMessage)
-
-    def getRawData(self) -> pd.DataFrame:
-        """Get the raw data.
-
-        Returns:
-            pd.DataFrame: The raw data.
-        """
-        df = pd.DataFrame(self.newData, columns=self.columns)
-        self.rawData = pd.concat([self.rawData, df], ignore_index=True)
-        self.newData = []
-
-        return self.rawData
-
-    def _exitHandler(self) -> None:
-        """Exit handler."""
-        fn = "/tmp/powermon.csv"  # Find a better place
-        logging.info(f"Storing PowerMon raw data in {fn}")
-        self.getRawData().to_csv(fn)
-
-    def _onLogMessage(self, ev: Event) -> None:
-        """Callback function for handling log messages.
-
-        Args:
-            ev (Event): The log event.
-        """
-        m = logRegex.match(ev.message)
-        if m:
-            mask = int(m.group(1), 16)
-            reason = m.group(2)
-            logging.debug(f"PowerMon state: 0x{mask:x}, reason: {reason}")
-            if mask != self.state:
-                self._storeRecord(mask, reason)
-
-    def _storeRecord(self, mask: int, reason: str) -> None:
-        """Store a power mon record.
-
-        Args:
-            mask (int): The power mon state bitfields.
-            reason (str): The reason for the power mon state change.
-        """
-        now = datetime.now()
-        nowWattHour = self.power.getWattHour()
-        watts = (
-            (nowWattHour - self.prevWattHour)
-            / (now - self.prevPowerTime).total_seconds()
-            * 3600
-        )
-        self.prevPowerTime = now
-        self.prevWattHour = nowWattHour
-        self.state = mask
-
-        self.newData.append(
-            {"time": now, "power": watts, "reason": reason, "bitmask": mask}
-        )

meshtastic/slog/slog.py

@@ -0,0 +1,103 @@
+"""code logging power consumption of meshtastic devices."""
+
+import logging
+import re
+import atexit
+from datetime import datetime
+from dataclasses import dataclass
+
+import parse
+import pandas as pd
+
+from meshtastic.mesh_interface import MeshInterface
+from meshtastic.observable import Event
+from meshtastic.powermon import PowerMeter
+
+
+@dataclass(init=False)
+class LogDef:
+    """Log definition."""
+    code: str           # i.e. PM or B or whatever... see meshtastic slog documentation
+    format: str         # A format string that can be used to parse the arguments
+
+    def __init__(self, code: str, format: str) -> None:
+        """Initialize the LogDef object.
+
+            code (str): The code.
+            format (str): The format.
+        """
+        self.code = code
+        self.format = parse.compile(format)
+
+"""A dictionary mapping from logdef code to logdef"""
+log_defs = {d.code: d for d in [
+    LogDef("B", "{boardid:d},{version}"),
+    LogDef("PM", "{bitmask:d},{reason}")
+    ]}
+log_regex = re.compile(".*S:([0-9A-Za-z]+):(.*)")
+
+
+class StructuredLogger:
+    """Sniffs device logs for structured log messages, extracts those into pandas/CSV format."""
+
+    def __init__(self, client: MeshInterface, pMeter: PowerMeter = None) -> None:
+        """Initialize the PowerMonClient object.
+
+            power (PowerSupply): The power supply object.
+            client (MeshInterface): The MeshInterface object to monitor.
+        """
+        self.client = client
+        self.pMeter = pMeter
+        self.columns = ["time", "power"]
+        self.rawData = pd.DataFrame(columns=self.columns)  # use time as the index
+
+        # for efficiency reasons we keep new data in a list - only adding to rawData when needed
+        self.newData: list[dict] = []
+
+        atexit.register(self._exitHandler)
+        client.onLogMessage.subscribe(self._onLogMessage)
+
+    def getRawData(self) -> pd.DataFrame:
+        """Get the raw data.
+
+        Returns
+        -------
+            pd.DataFrame: The raw data.
+        """
+        df = pd.DataFrame(self.newData, columns=self.columns)
+        self.rawData = pd.concat([self.rawData, df], ignore_index=True)
+        self.newData = []
+
+        return self.rawData
+
+    def _exitHandler(self) -> None:
+        """Exit handler."""
+        fn = "/tmp/powermon.slog"  # Find a better place
+        logging.info(f"Storing slog in {fn}")
+        self.getRawData().to_csv(fn)
+
+    def _onLogMessage(self, ev: Event) -> None:
+        """Handle log messages.
+
+            ev (Event): The log event.
+        """
+        m = log_regex.match(ev.message)
+        if m:
+            src = m.group(1)
+            args = m.group(2)
+
+            args += " "  # append a space so that if the last arg is an empty str it will still be accepted as a match
+            logging.debug(f"SLog {src}, reason: {args}")
+            d = log_defs.get(src)
+            if d:
+                r = d.format.parse(args) # get the values with the correct types
+                if r:
+                    di = r.named
+                    di["time"] = datetime.now()
+                    if self.pMeter: # if we have a power meter include a fresh power reading
+                        di["power"] = self.pMeter.getWatts()
+                    self.newData.append(di)
+                else:
+                    logging.warning(f"Failed to parse slog {ev.message} with {d.format}")
+            else:
+                logging.warning(f"Unknown Structured Log: {ev.message}")

poetry.lock

@@ -864,6 +864,17 @@ numpy = [
 ]
 types-pytz = ">=2022.1.1"
 
+[[package]]
+name = "parse"
+version = "1.20.2"
+description = "parse() is the opposite of format()"
+optional = false
+python-versions = "*"
+files = [
+    {file = "parse-1.20.2-py2.py3-none-any.whl", hash = "sha256:967095588cb802add9177d0c0b6133b5ba33b1ea9007ca800e526f42a85af558"},
+    {file = "parse-1.20.2.tar.gz", hash = "sha256:b41d604d16503c79d81af5165155c0b20f6c8d6c559efa66b4b695c3e5a0a0ce"},
+]
+
 [[package]]
 name = "pdoc3"
 version = "0.10.0"
@@ -1812,4 +1823,4 @@ tunnel = []
 [metadata]
 lock-version = "2.0"
 python-versions = "^3.9,<3.13"
-content-hash = "8263f20a372fbae7bf88b74a40931cb9e8b6b49d12942d91d960c12142b5a979"
+content-hash = "109915f24859629e5ec50dd761be8fcaa72fb327d724da8f18f266e9f2a3e4db"

pyproject.toml

@@ -31,6 +31,7 @@ types-pyyaml = "^6.0.12.20240311"
 packaging = "^24.0"
 riden = {git = "https://github.com/geeksville/riden.git#1.2.1"}
 pandas = "^2.2.2"
+parse = "^1.20.2"
 
 [tool.poetry.group.dev.dependencies]
 hypothesis = "^6.103.2"