Macro to trace log all MeshPackets as JSON (#4336)

* Macro to trace log all MeshPackets as JSON

* Comment

* Add trace logging to file for native target

* bytes to hex

* Add time_ms

---------

Co-authored-by: Jonathan Bennett <jbennett@incomsystems.biz>

bin/config-dist.yaml

@@ -135,10 +135,11 @@ Input:
 
 Logging:
   LogLevel: info # debug, info, warn, error
+#  TraceFile: /var/log/meshtasticd.json
 
 Webserver:
 #  Port: 443 # Port for Webserver & Webservices
 #  RootPath: /usr/share/doc/meshtasticd/web # Root Dir of WebServer
 
 General:
-  MaxNodes: 200
+  MaxNodes: 200

src/RedirectablePrint.cpp

@@ -49,7 +49,11 @@ size_t RedirectablePrint::write(uint8_t c)
 size_t RedirectablePrint::vprintf(const char *logLevel, const char *format, va_list arg)
 {
     va_list copy;
+#if ENABLE_JSON_LOGGING || ARCH_PORTDUINO
+    static char printBuf[512];
+#else
     static char printBuf[160];
+#endif
 
     va_copy(copy, arg);
     size_t len = vsnprintf(printBuf, sizeof(printBuf), format, copy);
@@ -98,6 +102,8 @@ void RedirectablePrint::log_to_serial(const char *logLevel, const char *format,
             Print::write("\u001b[33m", 6);
         if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_ERROR) == 0)
             Print::write("\u001b[31m", 6);
+        if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_TRACE) == 0)
+            Print::write("\u001b[35m", 6);
         uint32_t rtc_sec = getValidTime(RTCQuality::RTCQualityDevice, true); // display local time on logfile
         if (rtc_sec > 0) {
             long hms = rtc_sec % SEC_PER_DAY;
@@ -244,7 +250,21 @@ meshtastic_LogRecord_Level RedirectablePrint::getLogLevel(const char *logLevel)
 
 void RedirectablePrint::log(const char *logLevel, const char *format, ...)
 {
-#ifdef ARCH_PORTDUINO
+#if ARCH_PORTDUINO
+    // level trace is special, two possible ways to handle it.
+    if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_TRACE) == 0) {
+        if (settingsStrings[traceFilename] != "") {
+            va_list arg;
+            va_start(arg, format);
+            try {
+                traceFile << va_arg(arg, char *) << std::endl;
+            } catch (const std::ios_base::failure &e) {
+            }
+            va_end(arg);
+        }
+        if (settingsMap[logoutputlevel] < level_trace && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_TRACE) == 0)
+            return;
+    }
     if (settingsMap[logoutputlevel] < level_debug && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_DEBUG) == 0)
         return;
     else if (settingsMap[logoutputlevel] < level_info && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_INFO) == 0)

src/mesh/Router.cpp

@@ -11,6 +11,12 @@
 #if !MESHTASTIC_EXCLUDE_MQTT
 #include "mqtt/MQTT.h"
 #endif
+#if ARCH_PORTDUINO
+#include "platform/portduino/PortduinoGlue.h"
+#endif
+#if ENABLE_JSON_LOGGING || ARCH_PORTDUINO
+#include "serialization/MeshPacketSerializer.h"
+#endif
 /**
  * Router todo
  *
@@ -356,6 +362,13 @@ bool perhapsDecode(meshtastic_MeshPacket *p)
                 } */
 
                 printPacket("decoded message", p);
+#if ENABLE_JSON_LOGGING
+                LOG_TRACE("%s\n", MeshPacketSerializer::JsonSerialize(p, false).c_str());
+#elif ARCH_PORTDUINO
+                if (settingsStrings[traceFilename] != "" || settingsMap[logoutputlevel] == level_trace) {
+                    LOG_TRACE("%s\n", MeshPacketSerializer::JsonSerialize(p, false).c_str());
+                }
+#endif
                 return true;
             }
         }
@@ -491,6 +504,17 @@ void Router::handleReceived(meshtastic_MeshPacket *p, RxSource src)
 
 void Router::perhapsHandleReceived(meshtastic_MeshPacket *p)
 {
+#if ENABLE_JSON_LOGGING
+    // Even ignored packets get logged in the trace
+    p->rx_time = getValidTime(RTCQualityFromNet); // store the arrival timestamp for the phone
+    LOG_TRACE("%s\n", MeshPacketSerializer::JsonSerializeEncrypted(p).c_str());
+#elif ARCH_PORTDUINO
+    // Even ignored packets get logged in the trace
+    if (settingsStrings[traceFilename] != "" || settingsMap[logoutputlevel] == level_trace) {
+        p->rx_time = getValidTime(RTCQualityFromNet); // store the arrival timestamp for the phone
+        LOG_TRACE("%s\n", MeshPacketSerializer::JsonSerializeEncrypted(p).c_str());
+    }
+#endif
     // assert(radioConfig.has_preferences);
     bool ignore = is_in_repeated(config.lora.ignore_incoming, p->from) || (config.lora.ignore_mqtt && p->via_mqtt);
 

src/platform/portduino/PortduinoGlue.cpp

@@ -17,6 +17,7 @@
 
 std::map<configNames, int> settingsMap;
 std::map<configNames, std::string> settingsStrings;
+std::ofstream traceFile;
 char *configPath = nullptr;
 
 // FIXME - move setBluetoothEnable into a HALPlatform class
@@ -134,7 +135,9 @@ void portduinoSetup()
 
     try {
         if (yamlConfig["Logging"]) {
-            if (yamlConfig["Logging"]["LogLevel"].as<std::string>("info") == "debug") {
+            if (yamlConfig["Logging"]["LogLevel"].as<std::string>("info") == "trace") {
+                settingsMap[logoutputlevel] = level_trace;
+            } else if (yamlConfig["Logging"]["LogLevel"].as<std::string>("info") == "debug") {
                 settingsMap[logoutputlevel] = level_debug;
             } else if (yamlConfig["Logging"]["LogLevel"].as<std::string>("info") == "info") {
                 settingsMap[logoutputlevel] = level_info;
@@ -143,6 +146,7 @@ void portduinoSetup()
             } else if (yamlConfig["Logging"]["LogLevel"].as<std::string>("info") == "error") {
                 settingsMap[logoutputlevel] = level_error;
             }
+            settingsStrings[traceFilename] = yamlConfig["Logging"]["TraceFile"].as<std::string>("");
         }
         if (yamlConfig["Lora"]) {
             settingsMap[use_sx1262] = false;
@@ -346,6 +350,14 @@ void portduinoSetup()
     if (settingsStrings[spidev] != "") {
         SPI.begin(settingsStrings[spidev].c_str());
     }
+    if (settingsStrings[traceFilename] != "") {
+        try {
+            traceFile.open(settingsStrings[traceFilename], std::ios::out | std::ios::app);
+        } catch (std::ofstream::failure &e) {
+            std::cout << "*** traceFile Exception " << e.what() << std::endl;
+            exit(EXIT_FAILURE);
+        }
+    }
     return;
 }
 

src/platform/portduino/PortduinoGlue.h

@@ -1,4 +1,5 @@
 #pragma once
+#include <fstream>
 #include <map>
 
 enum configNames {
@@ -46,6 +47,7 @@ enum configNames {
     displayInvert,
     keyboardDevice,
     logoutputlevel,
+    traceFilename,
     webserver,
     webserverport,
     webserverrootpath,
@@ -53,8 +55,9 @@ enum configNames {
 };
 enum { no_screen, x11, st7789, st7735, st7735s, st7796, ili9341, ili9488, hx8357d };
 enum { no_touchscreen, xpt2046, stmpe610, gt911, ft5x06 };
-enum { level_error, level_warn, level_info, level_debug };
+enum { level_error, level_warn, level_info, level_debug, level_trace };
 
 extern std::map<configNames, int> settingsMap;
 extern std::map<configNames, std::string> settingsStrings;
+extern std::ofstream traceFile;
 int initGPIOPin(int pinNum, std::string gpioChipname);

src/serialization/MeshPacketSerializer.cpp

@@ -11,7 +11,7 @@
 #endif
 #include "mesh/generated/meshtastic/remote_hardware.pb.h"
 
-std::string MeshPacketSerializer::JsonSerialize(meshtastic_MeshPacket *mp, bool shouldLog)
+std::string MeshPacketSerializer::JsonSerialize(const meshtastic_MeshPacket *mp, bool shouldLog)
 {
     // the created jsonObj is immutable after creation, so
     // we need to do the heavy lifting before assembling it.
@@ -312,6 +312,38 @@ std::string MeshPacketSerializer::JsonSerialize(meshtastic_MeshPacket *mp, bool
     if (shouldLog)
         LOG_INFO("serialized json message: %s\n", jsonStr.c_str());
 
+    delete value;
+    return jsonStr;
+}
+
+std::string MeshPacketSerializer::JsonSerializeEncrypted(const meshtastic_MeshPacket *mp)
+{
+    JSONObject jsonObj;
+
+    jsonObj["id"] = new JSONValue((unsigned int)mp->id);
+    jsonObj["time_ms"] = new JSONValue((double)millis());
+    jsonObj["timestamp"] = new JSONValue((unsigned int)mp->rx_time);
+    jsonObj["to"] = new JSONValue((unsigned int)mp->to);
+    jsonObj["from"] = new JSONValue((unsigned int)mp->from);
+    jsonObj["channel"] = new JSONValue((unsigned int)mp->channel);
+    jsonObj["want_ack"] = new JSONValue(mp->want_ack);
+
+    if (mp->rx_rssi != 0)
+        jsonObj["rssi"] = new JSONValue((int)mp->rx_rssi);
+    if (mp->rx_snr != 0)
+        jsonObj["snr"] = new JSONValue((float)mp->rx_snr);
+    if (mp->hop_start != 0 && mp->hop_limit <= mp->hop_start) {
+        jsonObj["hops_away"] = new JSONValue((unsigned int)(mp->hop_start - mp->hop_limit));
+        jsonObj["hop_start"] = new JSONValue((unsigned int)(mp->hop_start));
+    }
+    jsonObj["size"] = new JSONValue((unsigned int)mp->encrypted.size);
+    auto encryptedStr = bytesToHex(mp->encrypted.bytes, mp->encrypted.size);
+    jsonObj["bytes"] = new JSONValue(encryptedStr.c_str());
+
+    // serialize and write it to the stream
+    JSONValue *value = new JSONValue(jsonObj);
+    std::string jsonStr = value->Stringify();
+
     delete value;
     return jsonStr;
 }

src/serialization/MeshPacketSerializer.h

@@ -1,8 +1,23 @@
 #include <meshtastic/mesh.pb.h>
 #include <string>
 
+static const char hexChars[16] = {'0', '1', '2', '3', '4', '5', '6', '7', '8', '9', 'A', 'B', 'C', 'D', 'E', 'F'};
+
 class MeshPacketSerializer
 {
   public:
-    static std::string JsonSerialize(meshtastic_MeshPacket *mp, bool shouldLog = true);
+    static std::string JsonSerialize(const meshtastic_MeshPacket *mp, bool shouldLog = true);
+    static std::string JsonSerializeEncrypted(const meshtastic_MeshPacket *mp);
+
+  private:
+    static std::string bytesToHex(const uint8_t *bytes, int len)
+    {
+        std::string result = "";
+        for (int i = 0; i < len; ++i) {
+            char const byte = bytes[i];
+            result += hexChars[(byte & 0xF0) >> 4];
+            result += hexChars[(byte & 0x0F) >> 0];
+        }
+        return result;
+    }
 };