When talking via serial, encapsulate log messages in protobufs if necessary

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,6 +80,134 @@ size_t RedirectablePrint::vprintf(const char *logLevel, const char *format, va_l
     return len;
 }
 
+void RedirectablePrint::log_to_serial(const char *logLevel, const char *format, va_list arg)
+{
+    size_t r = 0;
+
+    // Cope with 0 len format strings, but look for new line terminator
+    bool hasNewline = *format && format[strlen(format) - 1] == '\n';
+
+    // If we are the first message on a report, include the header
+    if (!isContinuationMessage) {
+        if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_DEBUG) == 0)
+            Print::write("\u001b[34m", 6);
+        if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_INFO) == 0)
+            Print::write("\u001b[32m", 6);
+        if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_WARN) == 0)
+            Print::write("\u001b[33m", 6);
+        if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_ERROR) == 0)
+            Print::write("\u001b[31m", 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;
+            // hms += tz.tz_dsttime * SEC_PER_HOUR;
+            // hms -= tz.tz_minuteswest * SEC_PER_MIN;
+            // mod `hms` to ensure in positive range of [0...SEC_PER_DAY)
+            hms = (hms + SEC_PER_DAY) % SEC_PER_DAY;
+
+            // Tear apart hms into h:m:s
+            int hour = hms / SEC_PER_HOUR;
+            int min = (hms % SEC_PER_HOUR) / SEC_PER_MIN;
+            int sec = (hms % SEC_PER_HOUR) % SEC_PER_MIN; // or hms % SEC_PER_MIN
+#ifdef ARCH_PORTDUINO
+            ::printf("%s \u001b[0m| %02d:%02d:%02d %u ", logLevel, hour, min, sec, millis() / 1000);
+#else
+            printf("%s \u001b[0m| %02d:%02d:%02d %u ", logLevel, hour, min, sec, millis() / 1000);
+#endif
+        } else
+#ifdef ARCH_PORTDUINO
+            ::printf("%s \u001b[0m| ??:??:?? %u ", logLevel, millis() / 1000);
+#else
+            printf("%s \u001b[0m| ??:??:?? %u ", logLevel, millis() / 1000);
+#endif
+
+        auto thread = concurrency::OSThread::currentThread;
+        if (thread) {
+            print("[");
+            // printf("%p ", thread);
+            // assert(thread->ThreadName.length());
+            print(thread->ThreadName);
+            print("] ");
+        }
+    }
+    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()) {
+        int ll = 0;
+        switch (logLevel[0]) {
+        case 'D':
+            ll = SYSLOG_DEBUG;
+            break;
+        case 'I':
+            ll = SYSLOG_INFO;
+            break;
+        case 'W':
+            ll = SYSLOG_WARN;
+            break;
+        case 'E':
+            ll = SYSLOG_ERR;
+            break;
+        case 'C':
+            ll = SYSLOG_CRIT;
+            break;
+        default:
+            ll = 0;
+        }
+        auto thread = concurrency::OSThread::currentThread;
+        if (thread) {
+            syslog.vlogf(ll, thread->ThreadName.c_str(), format, arg);
+        } else {
+            syslog.vlogf(ll, format, arg);
+        }
+    }
+#endif
+}
+
+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
+        isBleConnected = nimbleBluetooth && nimbleBluetooth->isActive() && nimbleBluetooth->isConnected();
+#elif defined(ARCH_NRF52)
+        isBleConnected = nrf52Bluetooth != nullptr && nrf52Bluetooth->isConnected();
+#endif
+        if (isBleConnected) {
+            char *message;
+            size_t initialLen;
+            size_t len;
+            initialLen = strlen(format);
+            message = new char[initialLen + 1];
+            len = vsnprintf(message, initialLen + 1, format, arg);
+            if (len > initialLen) {
+                delete[] message;
+                message = new char[len + 1];
+                vsnprintf(message, len + 1, format, arg);
+            }
+            auto thread = concurrency::OSThread::currentThread;
+#ifdef ARCH_ESP32
+            if (thread)
+                nimbleBluetooth->sendLog(mt_sprintf("%s | [%s] %s", logLevel, thread->ThreadName.c_str(), message).c_str());
+            else
+                nimbleBluetooth->sendLog(mt_sprintf("%s | %s", logLevel, message).c_str());
+#elif defined(ARCH_NRF52)
+            if (thread)
+                nrf52Bluetooth->sendLog(mt_sprintf("%s | [%s] %s", logLevel, thread->ThreadName.c_str(), message).c_str());
+            else
+                nrf52Bluetooth->sendLog(mt_sprintf("%s | %s", logLevel, message).c_str());
+#endif
+            delete[] message;
+        }
+    }
+}
+
 void RedirectablePrint::log(const char *logLevel, const char *format, ...)
 {
 #ifdef ARCH_PORTDUINO
@@ -109,122 +232,10 @@ void RedirectablePrint::log(const char *logLevel, const char *format, ...)
         va_list arg;
         va_start(arg, format);
 
-        // Cope with 0 len format strings, but look for new line terminator
-        bool hasNewline = *format && format[strlen(format) - 1] == '\n';
-
-        // If we are the first message on a report, include the header
-        if (!isContinuationMessage) {
-            if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_DEBUG) == 0)
-                Print::write("\u001b[34m", 6);
-            if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_INFO) == 0)
-                Print::write("\u001b[32m", 6);
-            if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_WARN) == 0)
-                Print::write("\u001b[33m", 6);
-            if (strcmp(logLevel, MESHTASTIC_LOG_LEVEL_ERROR) == 0)
-                Print::write("\u001b[31m", 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;
-                // hms += tz.tz_dsttime * SEC_PER_HOUR;
-                // hms -= tz.tz_minuteswest * SEC_PER_MIN;
-                // mod `hms` to ensure in positive range of [0...SEC_PER_DAY)
-                hms = (hms + SEC_PER_DAY) % SEC_PER_DAY;
+        log_to_serial(logLevel, format, arg);
+        log_to_syslog(logLevel, format, arg);
+        log_to_ble(logLevel, format, arg);
 
-                // Tear apart hms into h:m:s
-                int hour = hms / SEC_PER_HOUR;
-                int min = (hms % SEC_PER_HOUR) / SEC_PER_MIN;
-                int sec = (hms % SEC_PER_HOUR) % SEC_PER_MIN; // or hms % SEC_PER_MIN
-#ifdef ARCH_PORTDUINO
-                ::printf("%s \u001b[0m| %02d:%02d:%02d %u ", logLevel, hour, min, sec, millis() / 1000);
-#else
-                printf("%s \u001b[0m| %02d:%02d:%02d %u ", logLevel, hour, min, sec, millis() / 1000);
-#endif
-            } else
-#ifdef ARCH_PORTDUINO
-                ::printf("%s \u001b[0m| ??:??:?? %u ", logLevel, millis() / 1000);
-#else
-                printf("%s \u001b[0m| ??:??:?? %u ", logLevel, millis() / 1000);
-#endif
-
-            auto thread = concurrency::OSThread::currentThread;
-            if (thread) {
-                print("[");
-                // printf("%p ", thread);
-                // assert(thread->ThreadName.length());
-                print(thread->ThreadName);
-                print("] ");
-            }
-        }
-        vprintf(logLevel, format, 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()) {
-            int ll = 0;
-            switch (logLevel[0]) {
-            case 'D':
-                ll = SYSLOG_DEBUG;
-                break;
-            case 'I':
-                ll = SYSLOG_INFO;
-                break;
-            case 'W':
-                ll = SYSLOG_WARN;
-                break;
-            case 'E':
-                ll = SYSLOG_ERR;
-                break;
-            case 'C':
-                ll = SYSLOG_CRIT;
-                break;
-            default:
-                ll = 0;
-            }
-            auto thread = concurrency::OSThread::currentThread;
-            if (thread) {
-                syslog.vlogf(ll, thread->ThreadName.c_str(), format, arg);
-            } else {
-                syslog.vlogf(ll, format, arg);
-            }
-        }
-#endif
-
-        isContinuationMessage = !hasNewline;
-
-        if (config.bluetooth.device_logging_enabled && !pauseBluetoothLogging) {
-            bool isBleConnected = false;
-#ifdef ARCH_ESP32
-            isBleConnected = nimbleBluetooth && nimbleBluetooth->isActive() && nimbleBluetooth->isConnected();
-#elif defined(ARCH_NRF52)
-            isBleConnected = nrf52Bluetooth != nullptr && nrf52Bluetooth->isConnected();
-#endif
-            if (isBleConnected) {
-                char *message;
-                size_t initialLen;
-                size_t len;
-                initialLen = strlen(format);
-                message = new char[initialLen + 1];
-                len = vsnprintf(message, initialLen + 1, format, arg);
-                if (len > initialLen) {
-                    delete[] message;
-                    message = new char[len + 1];
-                    vsnprintf(message, len + 1, format, arg);
-                }
-                auto thread = concurrency::OSThread::currentThread;
-#ifdef ARCH_ESP32
-                if (thread)
-                    nimbleBluetooth->sendLog(mt_sprintf("%s | [%s] %s", logLevel, thread->ThreadName.c_str(), message).c_str());
-                else
-                    nimbleBluetooth->sendLog(mt_sprintf("%s | %s", logLevel, message).c_str());
-#elif defined(ARCH_NRF52)
-                if (thread)
-                    nrf52Bluetooth->sendLog(mt_sprintf("%s | [%s] %s", logLevel, thread->ThreadName.c_str(), message).c_str());
-                else
-                    nrf52Bluetooth->sendLog(mt_sprintf("%s | %s", logLevel, message).c_str());
-#endif
-                delete[] message;
-            }
-        }
         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,13 +80,40 @@ 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);
     } else {
         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,10 +36,13 @@ 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
 void consolePrintf(const char *format, ...);
 void consoleInit();
 
-extern SerialConsole *console;
+extern SerialConsole *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