From 0e45637f2c3efd483b40b2b17ec93c5d00b5ecf8 Mon Sep 17 00:00:00 2001 From: Kevin Hester Date: Sat, 22 Jun 2024 14:46:08 -0700 Subject: [PATCH] generalize the powermon stuff to become structured logging --- .vscode/settings.json | 3 + meshtastic/__main__.py | 13 +++-- meshtastic/powermon/riden.py | 29 ++++++++-- meshtastic/slog/__init__.py | 3 + meshtastic/slog/power_mon.py | 97 --------------------------------- meshtastic/slog/slog.py | 103 +++++++++++++++++++++++++++++++++++ poetry.lock | 13 ++++- pyproject.toml | 1 + 8 files changed, 154 insertions(+), 108 deletions(-) delete mode 100644 meshtastic/slog/power_mon.py create mode 100644 meshtastic/slog/slog.py diff --git a/.vscode/settings.json b/.vscode/settings.json index 5deb062..a1fd574 100644 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -1,6 +1,9 @@ { "cSpell.words": [ + "bitmask", + "boardid", "Meshtastic", + "powermon", "TORADIO", "Vids" ], diff --git a/meshtastic/__main__.py b/meshtastic/__main__.py index 3593edf..4a21e85 100644 --- a/meshtastic/__main__.py +++ b/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) diff --git a/meshtastic/powermon/riden.py b/meshtastic/powermon/riden.py index 8d7c131..1dd65bc 100644 --- a/meshtastic/powermon/riden.py +++ b/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 diff --git a/meshtastic/slog/__init__.py b/meshtastic/slog/__init__.py index e69de29..a96ae8e 100644 --- a/meshtastic/slog/__init__.py +++ b/meshtastic/slog/__init__.py @@ -0,0 +1,3 @@ +"""Structured logging framework (see dev docs for more info)""" + +from .slog import StructuredLogger diff --git a/meshtastic/slog/power_mon.py b/meshtastic/slog/power_mon.py deleted file mode 100644 index c1fd12e..0000000 --- a/meshtastic/slog/power_mon.py +++ /dev/null @@ -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} - ) diff --git a/meshtastic/slog/slog.py b/meshtastic/slog/slog.py new file mode 100644 index 0000000..17910e7 --- /dev/null +++ b/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}") diff --git a/poetry.lock b/poetry.lock index 0c6851f..b2ea4c6 100644 --- a/poetry.lock +++ b/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" diff --git a/pyproject.toml b/pyproject.toml index 622473a..2f53954 100644 --- a/pyproject.toml +++ b/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"