Switch to logging JSON for better tool integration

check-mate.py

@@ -8,6 +8,7 @@
 import time
 
 from pubsub import pub
+from pythonjsonlogger import jsonlogger
 
 import meshtastic
 import meshtastic.tcp_interface
@@ -35,33 +36,37 @@ def start(self):
 
         while True:
             try:
-                self.logger.info("[Connecting to %s...]", self.host)
+                self.logger.info("Connecting...", extra={"host": self.host})
                 self.connected = True
                 self.iface = meshtastic.tcp_interface.TCPInterface(hostname=self.host)
                 try:
                     while self.connected:
                         time.sleep(5)
                 except KeyboardInterrupt:
                     # On keyboard interrupt, close the connection and exit.
-                    self.logger.info("[Shutting down...]")
+                    self.logger.info("Shutting down...", extra={"host": self.host})
                     self.iface.close()
                     return 0
 
             except Exception as ex:
-                self.logger.error("Error with connection to %s : %s", self.host, ex)
-                self.logger.info("[Retrying in 5 seconds...]")
+                self.logger.error(
+                    "Error with connection: %s",
+                    ex,
+                    extra={"host": self.host, "error": ex},
+                )
+                self.logger.info("Retrying in 5 seconds...")
                 time.sleep(5)
 
     def onConnect(self, interface, topic=pub.AUTO_TOPIC):
         """called when we (re)connect to the radio"""
         if interface.nodes:
             for node in interface.nodes.values():
                 self.updateUser(node["user"])
-        self.logger.info("[Connected...]")
+        self.logger.info("Connected...")
 
     def onDisconnect(self, interface, topic=pub.AUTO_TOPIC):
         """called when we disconnect from the radio"""
-        self.logger.info("[Disconnected... waiting for reconnect...]")
+        self.logger.info("Disconnected... waiting for reconnect...")
         self.connected = False
 
     def onReceive(self, packet, interface):
@@ -74,7 +79,7 @@ def onReceive(self, packet, interface):
                 if "user" in packet["decoded"]:
                     self.updateUser(packet["decoded"]["user"])
                 else:
-                    self.logger.info("Ignoring missing user: %s", packet)
+                    self.logger.info("Ignoring missing user", extra={"packet": packet})
                 return
 
             if self.isTextMessage(packet):
@@ -83,34 +88,40 @@ def onReceive(self, packet, interface):
                 name = self.getName(packet, interface)
 
                 if channel == 0:
-                    self.logger.info("[Ignoring default channel] %s: %s", name, text)
+                    self.logger.info(
+                        "Ignoring message to default channel",
+                        extra={"name": name, "text": text},
+                    )
                     return
 
                 if not re.search(r"(mesh|radio)\s*check", text, re.IGNORECASE):
                     self.logger.info(
-                        "[Not a radio check] %s (channel %d): %s %d",
-                        name,
-                        channel,
-                        text,
+                        "Not a radio check",
+                        extra={"name": name, "channel": channel, "text": text},
                     )
                     return
 
                 self.ackRadioCheck(packet, interface)
                 return
 
         except Exception as ex:
-            self.logger.warning("Error processing packet: %s // %v", ex, packet)
+            self.logger.warning(
+                "Error processing packet: %s",
+                ex,
+                extra={"packet": packet},
+            )
 
     def reportHealth(self):
         if self.healthCheckURL is not None:
             if self.lastHealthCheck is None or time.time() - self.lastHealthCheck > 60:
                 self.lastHealthCheck = time.time()
                 response = requests.head(self.healthCheckURL)
                 if response.status_code == 200:
-                    self.logger.info("[Healthcheck ❤️]")
+                    self.logger.info("Healthcheck ❤️")
                 else:
                     self.logger.warning(
-                        "Healthcheck failed with status code: %d", response.status_code
+                        "Healthcheck failed",
+                        extra={"statusCode": response.status_code},
                     )
 
     def ackRadioCheck(self, packet, interface):
@@ -122,12 +133,14 @@ def ackRadioCheck(self, packet, interface):
         name = self.getName(packet, interface)
 
         self.logger.info(
-            "[Acknowledging radio check]: %s (channel %d, %s rssi, %s snr): %s",
-            name,
-            channel,
-            rssi,
-            snr,
-            text,
+            "Acknowledging radio check",
+            extra={
+                "name": name,
+                "channel": channel,
+                "rssi": rssi,
+                "snr": snr,
+                "text": text,
+            },
         )
 
         interface.sendText(self.getMessage(snr, rssi, name), channelIndex=channel)
@@ -166,7 +179,8 @@ def updateUser(self, user):
         """Update the ID to name mapping"""
         self.users[user["id"]] = user["shortName"]
         self.logger.info(
-            "[Updating user identity] %s -> %s", user["id"], user["shortName"]
+            "Updating user identity",
+            extra={"id": user["id"], "shortName": user["shortName"]},
         )
 
     def isNodeInfo(self, packet):
@@ -206,13 +220,37 @@ def idToHex(self, nodeId):
         return "!" + hex(nodeId)[2:]
 
 
+# Basd on unit test here: https://github.com/madzak/python-json-logger/blob/5f85723f4693c7289724fdcda84cfc0b62da74d4/tests/test_jsonlogger.py#L87
+def getLogFormat():
+    supported_keys = [
+        "asctime",
+        "message",
+        "filename",
+        "funcName",
+        "levelname",
+        "lineno",
+    ]
+    log_format = lambda x: ["%({0:s})s".format(i) for i in x]
+    return " ".join(log_format(supported_keys))
+
+
 if __name__ == "__main__":
 
-    stdout_handler = logging.StreamHandler(stream=sys.stdout)
+    logHandler = logging.StreamHandler()
+    formatter = jsonlogger.JsonFormatter(
+        getLogFormat(),
+        rename_fields={
+            "asctime": "time",
+            "funcName": "function",
+            "levelname": "level",
+            "lineno": "line",
+        },
+        datefmt="%Y-%m-%dT%H:%M:%S.%fZ",
+    )
+    logHandler.setFormatter(formatter)
     logging.basicConfig(
         level=logging.INFO,
-        format="[%(asctime)s] {%(filename)s:%(lineno)d} %(levelname)s | %(message)s",
-        handlers=[stdout_handler],
+        handlers=[logHandler],
     )
 
     parser = argparse.ArgumentParser(

requirements.txt

@@ -1,2 +1,3 @@
 meshtastic==2.4.0
 pubsub==0.1.2
+python-json-logger==2.0.7