When talking via serial, encapsulate log messages in protobufs if necessary (#4187)

* clean up RedirectablePrint::log so it doesn't have three very different implementations inline.

* remove NoopPrint - it is no longer needed

* when talking to API clients via serial, don't turn off log msgs instead encapsuate them

* fix the build - would loop forever if there were no files to send

* don't use Segger code if not talking to a Segger debugger

* when encapsulating logs, make sure the strings always has nul terminators

* nrf52 soft device will watchdog if you use ICE while BT on...
so have debugger disable bluetooth.

* Important to not print debug messages while writing to the toPhone scratch buffer

* don't include newlines if encapsulating log records as protobufs

---------

Co-authored-by: Ben Meadors <benmmeadors@gmail.com>

src/RedirectablePrint.cpp

@@ -15,11 +15,6 @@
 #include "platform/portduino/PortduinoGlue.h"
 #endif
 
-/**
- * A printer that doesn't go anywhere
- */
-NoopPrint noopPrint;
-
 #if HAS_WIFI || HAS_ETHERNET
 extern Syslog syslog;
 #endif
@@ -39,7 +34,7 @@ void RedirectablePrint::setDestination(Print *_dest)
 size_t RedirectablePrint::write(uint8_t c)
 {
     // Always send the characters to our segger JTAG debugger
-#ifdef SEGGER_STDOUT_CH
+#ifdef USE_SEGGER
     SEGGER_RTT_PutChar(SEGGER_STDOUT_CH, c);
 #endif
 
@@ -85,29 +80,9 @@ size_t RedirectablePrint::vprintf(const char *logLevel, const char *format, va_l
     return len;
 }
 
-void RedirectablePrint::log(const char *logLevel, const char *format, ...)
+void RedirectablePrint::log_to_serial(const char *logLevel, const char *format, va_list arg)
 {
-#ifdef ARCH_PORTDUINO
-    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)
-        return;
-    else if (settingsMap[logoutputlevel] < level_warn && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_WARN) == 0)
-        return;
-#endif
-    if (moduleConfig.serial.override_console_serial_port && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_DEBUG) == 0) {
-        return;
-    }
-
-#ifdef HAS_FREE_RTOS
-    if (inDebugPrint != nullptr && xSemaphoreTake(inDebugPrint, portMAX_DELAY) == pdTRUE) {
-#else
-    if (!inDebugPrint) {
-        inDebugPrint = true;
-#endif
-
-        va_list arg;
-        va_start(arg, format);
+    size_t r = 0;
 
     // Cope with 0 len format strings, but look for new line terminator
     bool hasNewline = *format && format[strlen(format) - 1] == '\n';
@@ -155,8 +130,13 @@ void RedirectablePrint::log(const char *logLevel, const char *format, ...)
             print("] ");
         }
     }
-        vprintf(logLevel, format, arg);
+    r += vprintf(logLevel, format, arg);
 
+    isContinuationMessage = !hasNewline;
+}
+
+void RedirectablePrint::log_to_syslog(const char *logLevel, const char *format, va_list arg)
+{
 #if (HAS_WIFI || HAS_ETHERNET) && !defined(ARCH_PORTDUINO)
     // if syslog is in use, collect the log messages and send them to syslog
     if (syslog.isEnabled()) {
@@ -188,9 +168,10 @@ void RedirectablePrint::log(const char *logLevel, const char *format, ...)
         }
     }
 #endif
+}
 
-        isContinuationMessage = !hasNewline;
-
+void RedirectablePrint::log_to_ble(const char *logLevel, const char *format, va_list arg)
+{
     if (config.bluetooth.device_logging_enabled && !pauseBluetoothLogging) {
         bool isBleConnected = false;
 #ifdef ARCH_ESP32
@@ -225,6 +206,36 @@ void RedirectablePrint::log(const char *logLevel, const char *format, ...)
             delete[] message;
         }
     }
+}
+
+void RedirectablePrint::log(const char *logLevel, const char *format, ...)
+{
+#ifdef ARCH_PORTDUINO
+    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)
+        return;
+    else if (settingsMap[logoutputlevel] < level_warn && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_WARN) == 0)
+        return;
+#endif
+    if (moduleConfig.serial.override_console_serial_port && strcmp(logLevel, MESHTASTIC_LOG_LEVEL_DEBUG) == 0) {
+        return;
+    }
+
+#ifdef HAS_FREE_RTOS
+    if (inDebugPrint != nullptr && xSemaphoreTake(inDebugPrint, portMAX_DELAY) == pdTRUE) {
+#else
+    if (!inDebugPrint) {
+        inDebugPrint = true;
+#endif
+
+        va_list arg;
+        va_start(arg, format);
+
+        log_to_serial(logLevel, format, arg);
+        log_to_syslog(logLevel, format, arg);
+        log_to_ble(logLevel, format, arg);
+
         va_end(arg);
 #ifdef HAS_FREE_RTOS
         xSemaphoreGive(inDebugPrint);

src/RedirectablePrint.h

@@ -49,15 +49,12 @@ class RedirectablePrint : public Print
     void hexDump(const char *logLevel, unsigned char *buf, uint16_t len);
 
     std::string mt_sprintf(const std::string fmt_str, ...);
-};
 
-class NoopPrint : public Print
-{
-  public:
-    virtual size_t write(uint8_t c) { return 1; }
-};
+  protected:
+    /// Subclasses can override if they need to change how we format over the serial port
+    virtual void log_to_serial(const char *logLevel, const char *format, va_list arg);
 
-/**
- * A printer that doesn't go anywhere
- */
-extern NoopPrint noopPrint;
+  private:
+    void log_to_syslog(const char *logLevel, const char *format, va_list arg);
+    void log_to_ble(const char *logLevel, const char *format, va_list arg);
+};

src/SerialConsole.cpp

@@ -34,7 +34,6 @@ SerialConsole::SerialConsole() : StreamAPI(&Port), RedirectablePrint(&Port), con
     assert(!console);
     console = this;
     canWrite = false; // We don't send packets to our port until it has talked to us first
-                      // setDestination(&noopPrint); for testing, try turning off 'all' debug output and see what leaks
 
 #ifdef RP2040_SLOW_CLOCK
     Port.setTX(SERIAL2_TX);
@@ -81,9 +80,8 @@ bool SerialConsole::handleToRadio(const uint8_t *buf, size_t len)
 {
     // only talk to the API once the configuration has been loaded and we're sure the serial port is not disabled.
     if (config.has_lora && config.device.serial_enabled) {
-        // Turn off debug serial printing once the API is activated, because other threads could print and corrupt packets
-        if (!config.device.debug_log_enabled)
-            setDestination(&noopPrint);
+        // Switch to protobufs for log messages
+        usingProtobufs = true;
         canWrite = true;
 
         return StreamAPI::handleToRadio(buf, len);
@@ -91,3 +89,31 @@ bool SerialConsole::handleToRadio(const uint8_t *buf, size_t len)
         return false;
     }
 }
+
+void SerialConsole::log_to_serial(const char *logLevel, const char *format, va_list arg)
+{
+    if (usingProtobufs) {
+        meshtastic_LogRecord_Level ll = meshtastic_LogRecord_Level_UNSET; // default to unset
+        switch (logLevel[0]) {
+        case 'D':
+            ll = meshtastic_LogRecord_Level_DEBUG;
+            break;
+        case 'I':
+            ll = meshtastic_LogRecord_Level_INFO;
+            break;
+        case 'W':
+            ll = meshtastic_LogRecord_Level_WARNING;
+            break;
+        case 'E':
+            ll = meshtastic_LogRecord_Level_ERROR;
+            break;
+        case 'C':
+            ll = meshtastic_LogRecord_Level_CRITICAL;
+            break;
+        }
+
+        auto thread = concurrency::OSThread::currentThread;
+        emitLogRecord(ll, thread ? thread->ThreadName.c_str() : "", format, arg);
+    } else
+        RedirectablePrint::log_to_serial(logLevel, format, arg);
+}

src/SerialConsole.h

@@ -8,6 +8,11 @@
  */
 class SerialConsole : public StreamAPI, public RedirectablePrint, private concurrency::OSThread
 {
+    /**
+     * If true we are talking to a smart host and all messages (including log messages) must be framed as protobufs.
+     */
+    bool usingProtobufs = false;
+
   public:
     SerialConsole();
 
@@ -31,6 +36,9 @@ class SerialConsole : public StreamAPI, public RedirectablePrint, private concur
   protected:
     /// Check the current underlying physical link to see if the client is currently connected
     virtual bool checkIsConnected() override;
+
+    /// Possibly switch to protobufs if we see a valid protobuf message
+    virtual void log_to_serial(const char *logLevel, const char *format, va_list arg);
 };
 
 // A simple wrapper to allow non class aware code write to the console

src/main.cpp

@@ -221,7 +221,7 @@ void setup()
         meshtastic_Config_DisplayConfig_OledType::meshtastic_Config_DisplayConfig_OledType_OLED_AUTO;
     OLEDDISPLAY_GEOMETRY screen_geometry = GEOMETRY_128_64;
 
-#ifdef SEGGER_STDOUT_CH
+#ifdef USE_SEGGER
     auto mode = false ? SEGGER_RTT_MODE_BLOCK_IF_FIFO_FULL : SEGGER_RTT_MODE_NO_BLOCK_TRIM;
 #ifdef NRF52840_XXAA
     auto buflen = 4096; // this board has a fair amount of ram

src/mesh/PhoneAPI.cpp

@@ -407,7 +407,9 @@ size_t PhoneAPI::getFromRadio(uint8_t *buf)
         // Encapsulate as a FromRadio packet
         size_t numbytes = pb_encode_to_bytes(buf, meshtastic_FromRadio_size, &meshtastic_FromRadio_msg, &fromRadioScratch);
 
-        LOG_DEBUG("encoding toPhone packet to phone variant=%d, %d bytes\n", fromRadioScratch.which_payload_variant, numbytes);
+        // VERY IMPORTANT to not print debug messages while writing to fromRadioScratch - because we use that same buffer
+        // for logging (when we are encapsulating with protobufs)
+        // LOG_DEBUG("encoding toPhone packet to phone variant=%d, %d bytes\n", fromRadioScratch.which_payload_variant, numbytes);
         return numbytes;
     }
 

src/mesh/StreamAPI.cpp

@@ -1,5 +1,6 @@
 #include "StreamAPI.h"
 #include "PowerFSM.h"
+#include "RTC.h"
 #include "configuration.h"
 
 #define START1 0x94
@@ -96,7 +97,6 @@ void StreamAPI::writeStream()
 void StreamAPI::emitTxBuffer(size_t len)
 {
     if (len != 0) {
-        // LOG_DEBUG("emit tx %d\n", len);
         txBuf[0] = START1;
         txBuf[1] = START2;
         txBuf[2] = (len >> 8) & 0xff;
@@ -119,6 +119,25 @@ void StreamAPI::emitRebooted()
     emitTxBuffer(pb_encode_to_bytes(txBuf + HEADER_LEN, meshtastic_FromRadio_size, &meshtastic_FromRadio_msg, &fromRadioScratch));
 }
 
+void StreamAPI::emitLogRecord(meshtastic_LogRecord_Level level, const char *src, const char *format, va_list arg)
+{
+    // In case we send a FromRadio packet
+    memset(&fromRadioScratch, 0, sizeof(fromRadioScratch));
+    fromRadioScratch.which_payload_variant = meshtastic_FromRadio_log_record_tag;
+    fromRadioScratch.log_record.level = level;
+
+    uint32_t rtc_sec = getValidTime(RTCQuality::RTCQualityDevice, true);
+    fromRadioScratch.log_record.time = rtc_sec;
+    strncpy(fromRadioScratch.log_record.source, src, sizeof(fromRadioScratch.log_record.source) - 1);
+
+    auto num_printed =
+        vsnprintf(fromRadioScratch.log_record.message, sizeof(fromRadioScratch.log_record.message) - 1, format, arg);
+    if (num_printed > 0 && fromRadioScratch.log_record.message[num_printed - 1] ==
+                               '\n') // Strip any ending newline, because we have records for framing instead.
+        fromRadioScratch.log_record.message[num_printed - 1] = '\0';
+    emitTxBuffer(pb_encode_to_bytes(txBuf + HEADER_LEN, meshtastic_FromRadio_size, &meshtastic_FromRadio_msg, &fromRadioScratch));
+}
+
 /// Hookable to find out when connection changes
 void StreamAPI::onConnectionChanged(bool connected)
 {

src/mesh/StreamAPI.h

@@ -82,4 +82,7 @@ class StreamAPI : public PhoneAPI
 
     /// Subclasses can use this scratch buffer if they wish
     uint8_t txBuf[MAX_STREAM_BUF_SIZE] = {0};
+
+    /// Low level function to emit a protobuf encapsulated log record
+    void emitLogRecord(meshtastic_LogRecord_Level level, const char *src, const char *format, va_list arg);
 };