diff --git a/src/RedirectablePrint.cpp b/src/RedirectablePrint.cpp index 265bb42d6..782febd75 100644 --- a/src/RedirectablePrint.cpp +++ b/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'; + log_to_serial(logLevel, format, arg); + log_to_syslog(logLevel, format, arg); + log_to_ble(logLevel, format, arg); - // 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("] "); - } - } - 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); diff --git a/src/RedirectablePrint.h b/src/RedirectablePrint.h index a29ad9c74..3f20c894c 100644 --- a/src/RedirectablePrint.h +++ b/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; \ No newline at end of file + 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); +}; \ No newline at end of file diff --git a/src/SerialConsole.cpp b/src/SerialConsole.cpp index 41064f288..12b9d2bd0 100644 --- a/src/SerialConsole.cpp +++ b/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); } \ No newline at end of file diff --git a/src/SerialConsole.h b/src/SerialConsole.h index f8891ba14..f1e636c9d 100644 --- a/src/SerialConsole.h +++ b/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; \ No newline at end of file diff --git a/src/main.cpp b/src/main.cpp index 462eaa0f4..196eae525 100644 --- a/src/main.cpp +++ b/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 diff --git a/src/mesh/PhoneAPI.cpp b/src/mesh/PhoneAPI.cpp index 322b0cf5e..0f69b21f9 100644 --- a/src/mesh/PhoneAPI.cpp +++ b/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; } diff --git a/src/mesh/StreamAPI.cpp b/src/mesh/StreamAPI.cpp index 4d04dffe4..9f59aa971 100644 --- a/src/mesh/StreamAPI.cpp +++ b/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) { @@ -131,4 +150,4 @@ void StreamAPI::onConnectionChanged(bool connected) // received a packet in a while powerFSM.trigger(EVENT_SERIAL_DISCONNECTED); } -} +} \ No newline at end of file diff --git a/src/mesh/StreamAPI.h b/src/mesh/StreamAPI.h index 3196e96f8..45cbb231c 100644 --- a/src/mesh/StreamAPI.h +++ b/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); +}; \ No newline at end of file