Debug: store boot log (#2109)

* debug: store boot log

* order

* roll single header

* hide when not implemented

* fix capacity check

* dependencies

* refactor names, can just use malloc

* settings formatting

* dbgBuf prefix

* show size

* release memory after buffer is displayed

* fix uptime unused warning, combine printer

* comments

* use arg flag instead of static to handle boot

* ci test fix

* Hide whole info() without debug

* typo

* cleanup setDebugOutput condition

code/espurna/config/dependencies.h

@@ -129,3 +129,9 @@
 #undef WEB_SSL_ENABLED
 #define WEB_SSL_ENABLED          0               // WEB_SUPPORT mode th SSL requires ASYNC_TCP_SSL_ENABLED
 #endif
+
+#if not DEBUG_SUPPORT
+#undef DEBUG_LOG_BUFFER_SUPPORT
+#define DEBUG_LOG_BUFFER_SUPPORT  0              // Can't buffer if there is no debugging enabled.
+                                                 // Helps to avoid checking twice for both DEBUG_SUPPORT and BUFFER_LOG_SUPPORT
+#endif

code/espurna/config/general.h

@@ -102,6 +102,22 @@
 #define DEBUG_WEB_SUPPORT       1               // Enable web debug log (will only work if WEB_SUPPORT is also 1)
 #endif
 
+//------------------------------------------------------------------------------
+
+#ifndef DEBUG_LOG_BUFFER_SUPPORT
+#define DEBUG_LOG_BUFFER_SUPPORT       1        // Support boot log buffer (1.2Kb)
+                                                // Will only work if DEBUG_LOG_BUFFER_ENABLED or runtime setting is also 1
+#endif
+
+#ifndef DEBUG_LOG_BUFFER_ENABLED
+#define DEBUG_LOG_BUFFER_ENABLED       0        // Disable boot log buffer by default
+#endif
+
+#ifndef DEBUG_LOG_BUFFER_SIZE
+#define DEBUG_LOG_BUFFER_SIZE          4096     // Store 4 Kb of log strings
+                                                // WARNING! Memory is only reclaimed after `debug.buffer` prints the buffer contents
+#endif
+
 //------------------------------------------------------------------------------
 // TELNET
 //------------------------------------------------------------------------------

code/espurna/config/prototypes.h

@@ -83,20 +83,6 @@ using api_put_callback_f = std::function<void(const char * payload)> ;
     void apiRegister(const char * key, api_get_callback_f getFn, api_put_callback_f putFn = NULL);
 #endif
 
-// -----------------------------------------------------------------------------
-// Debug
-// -----------------------------------------------------------------------------
-
-#include "../libs/DebugSend.h"
-
-void debugSendImpl(const char*);
-extern "C" {
-     void custom_crash_callback(struct rst_info*, uint32_t, uint32_t);
-}
-
-class PrintRaw;
-class PrintHex;
-
 // Core version 2.4.2 and higher changed the cont_t structure to a pointer:
 // https://github.com/esp8266/Arduino/commit/5d5ea92a4d004ab009d5f642629946a0cb8893dd#diff-3fa12668b289ccb95b7ab334833a4ba8L35
 // Core version 2.5.0 introduced EspClass helper method:

code/espurna/debug.h

@@ -0,0 +1,21 @@
+/*
+
+DEBUG MODULE
+
+*/
+
+#pragma once
+
+extern "C" {
+     void custom_crash_callback(struct rst_info*, uint32_t, uint32_t);
+}
+
+class PrintRaw;
+class PrintHex;
+
+bool debugLogBuffer();
+void debugSend(const char* format, ...);
+void debugSend_P(PGM_P format_P, ...);
+
+void debugWebSetup();
+void debugSetup();

code/espurna/debug.ino

@@ -8,7 +8,10 @@ Copyright (C) 2016-2019 by Xose Pérez <xose dot perez at gmail dot com>
 
 #if DEBUG_SUPPORT
 
-#include "libs/DebugSend.h"
+#include <limits>
+#include <vector>
+
+#include "debug.h"
 
 #if DEBUG_UDP_SUPPORT
 #include <WiFiUdp.h>
@@ -18,6 +21,67 @@ char _udp_syslog_header[40] = {0};
 #endif
 #endif
 
+// -----------------------------------------------------------------------------
+// printf-like debug methods
+// -----------------------------------------------------------------------------
+
+constexpr const int DEBUG_SEND_STRING_BUFFER_SIZE = 128;
+
+void _debugSendInternal(const char * message, bool add_timestamp = DEBUG_ADD_TIMESTAMP);
+
+// TODO: switch to newlib vsnprintf for latest Cores to support PROGMEM args
+void _debugSend(const char * format, va_list args) {
+
+    char temp[DEBUG_SEND_STRING_BUFFER_SIZE];
+    int len = ets_vsnprintf(temp, sizeof(temp), format, args);
+
+    // strlen(...) + '\0' already in temp buffer, avoid using malloc when possible
+    if (len < DEBUG_SEND_STRING_BUFFER_SIZE) {
+        _debugSendInternal(temp);
+        return;
+    }
+
+    len += 1;
+    auto* buffer = static_cast<char*>(malloc(len));
+    if (!buffer) {
+        return;
+    }
+    ets_vsnprintf(buffer, len, format, args);
+
+    _debugSendInternal(buffer);
+    free(buffer);
+
+}
+
+void debugSend(const char* format, ...) {
+
+    va_list args;
+    va_start(args, format);
+
+    _debugSend(format, args);
+
+    va_end(args);
+
+}
+
+void debugSend_P(PGM_P format_P, ...) {
+
+    char format[strlen_P(format_P) + 1];
+    memcpy_P(format, format_P, sizeof(format));
+
+    va_list args;
+    va_start(args, format_P);
+
+    _debugSend(format, args);
+
+    va_end(args);
+
+}
+
+// -----------------------------------------------------------------------------
+// specific debug targets
+// -----------------------------------------------------------------------------
+
 #if DEBUG_SERIAL_SUPPORT
     void _debugSendSerial(const char* prefix, const char* data) {
         if (prefix && (prefix[0] != '\0')) {
@@ -26,7 +90,7 @@ char _udp_syslog_header[40] = {0};
         DEBUG_PORT.print(data);
 
     }
-#endif
+#endif // DEBUG_SERIAL_SUPPORT
 
 #if DEBUG_TELNET_SUPPORT
     void _debugSendTelnet(const char* prefix, const char* data) {
@@ -36,9 +100,44 @@ char _udp_syslog_header[40] = {0};
         _telnetWrite(data);
 
     }
-#endif
+#endif // DEBUG_TELNET_SUPPORT
+
+#if DEBUG_LOG_BUFFER_SUPPORT
+
+std::vector<char> _debug_log_buffer;
+bool _debug_log_buffer_enabled = false;
+
+void _debugLogBuffer(const char* prefix, const char* data) {
+    if (!_debug_log_buffer_enabled) return;
+
+    const auto prefix_len = strlen(prefix);
+    const auto data_len = strlen(data);
+    const auto total_len = prefix_len + data_len;
+    if (total_len >= std::numeric_limits<uint16_t>::max()) {
+        return;
+    }
+    if ((_debug_log_buffer.capacity() - _debug_log_buffer.size()) <= (total_len + 3)) {
+        _debug_log_buffer_enabled = false;
+        return;
+    }
+
+    _debug_log_buffer.push_back(total_len >> 8);
+    _debug_log_buffer.push_back(total_len & 0xff);
+    if (prefix && (prefix[0] != '\0')) {
+        _debug_log_buffer.insert(_debug_log_buffer.end(), prefix, prefix + prefix_len);
+    }
+    _debug_log_buffer.insert(_debug_log_buffer.end(), data, data + data_len);
+}
+
+bool debugLogBuffer() {
+    return _debug_log_buffer_enabled;
+}
 
-void debugSendImpl(const char * message) {
+#endif // DEBUG_LOG_BUFFER_SUPPORT
+
+// -----------------------------------------------------------------------------
+
+void _debugSendInternal(const char * message, bool add_timestamp) {
 
     const size_t msg_len = strlen(message);
 
@@ -46,11 +145,11 @@ void debugSendImpl(const char * message) {
     char timestamp[10] = {0};
 
     #if DEBUG_ADD_TIMESTAMP
-        static bool add_timestamp = true;
-        if (add_timestamp) {
+        static bool continue_timestamp = true;
+        if (add_timestamp && continue_timestamp) {
             snprintf(timestamp, sizeof(timestamp), "[%06lu] ", millis() % 1000000);
         }
-        add_timestamp = (message[msg_len - 1] == 10) || (message[msg_len - 1] == 13);
+        continue_timestamp = add_timestamp || (message[msg_len - 1] == 10) || (message[msg_len - 1] == 13);
     #endif
 
     #if DEBUG_SERIAL_SUPPORT
@@ -83,10 +182,15 @@ void debugSendImpl(const char * message) {
         pause = true;
     #endif
 
+    #if DEBUG_LOG_BUFFER_SUPPORT
+        _debugLogBuffer(timestamp, message);
+    #endif
+
     if (pause) optimistic_yield(100);
 
 }
 
+// -----------------------------------------------------------------------------
 
 #if DEBUG_WEB_SUPPORT
 
@@ -111,6 +215,7 @@ void debugWebSetup() {
         .onVisible([](JsonObject& root) { root["dbgVisible"] = 1; })
         .onAction(_debugWebSocketOnAction);
 
+    // TODO: if hostname string changes, need to update header too
     #if DEBUG_UDP_SUPPORT
     #if DEBUG_UDP_PORT == 514
         snprintf_P(_udp_syslog_header, sizeof(_udp_syslog_header), PSTR("<%u>%s ESPurna[0]: "), DEBUG_UDP_FAC_PRI, getSetting("hostname").c_str());
@@ -128,11 +233,64 @@ void debugSetup() {
 
     #if DEBUG_SERIAL_SUPPORT
         DEBUG_PORT.begin(SERIAL_BAUDRATE);
-        #if DEBUG_ESP_WIFI
-            DEBUG_PORT.setDebugOutput(true);
-        #endif
     #endif
 
+    // HardwareSerial::begin() will automatically enable this when
+    //  `#if defined(DEBUG_ESP_PORT) && !defined(NDEBUG)`
+    // Core debugging also depends on various DEBUG_ESP_... being defined
+    #define DEBUG_SERIAL_SDK (int)(defined(DEBUG_ESP_PORT) && !defined(NDEBUG))
+    if (getSetting("dbgSDK", DEBUG_SERIAL_SDK).toInt() == 1) {
+        DEBUG_PORT.setDebugOutput(true);
+    }
+    #undef DEBUG_SERIAL_SDK
+
+    #if DEBUG_LOG_BUFFER_SUPPORT
+    {
+        auto enabled = getSetting("dbgBufEnabled", DEBUG_LOG_BUFFER_ENABLED).toInt() == 1;
+        auto size = getSetting("dbgBufSize", DEBUG_LOG_BUFFER_SIZE).toInt();
+        if (enabled) {
+            _debug_log_buffer_enabled = true;
+            _debug_log_buffer.reserve(size);
+        }
+    }
+
+    #if TERMINAL_SUPPORT
+        terminalRegisterCommand(F("DEBUG.BUFFER"), [](Embedis* e) {
+            _debug_log_buffer_enabled = false;
+            if (!_debug_log_buffer.size()) {
+                DEBUG_MSG_P(PSTR("[DEBUG] Buffer is empty\n"));
+                return;
+            }
+            DEBUG_MSG_P(PSTR("[DEBUG] Buffer size: %u / %u bytes\n"),
+                _debug_log_buffer.size(),
+                _debug_log_buffer.capacity()
+            );
+
+            size_t index = 0;
+            do {
+                if (index >= _debug_log_buffer.size()) {
+                    break;
+                }
+
+                size_t len = _debug_log_buffer[index] << 8;
+                len = len | _debug_log_buffer[index + 1];
+                index += 2;
+
+                auto value = _debug_log_buffer[index + len];
+                _debug_log_buffer[index + len] = '\0';
+                _debugSendInternal(_debug_log_buffer.data() + index, false);
+                _debug_log_buffer[index + len] = value;
+
+                index += len;
+            } while (true);
+
+            _debug_log_buffer.clear();
+            _debug_log_buffer.shrink_to_fit();
+        });
+    #endif // TERMINAL_SUPPORT
+
+    #endif // DEBUG_LOG_BUFFER
+
 }
 
 #endif // DEBUG_SUPPORT

code/espurna/espurna.ino

@@ -22,11 +22,12 @@ along with this program.  If not, see <http://www.gnu.org/licenses/>.
 #include "config/all.h"
 #include <vector>
 
-#include "system.h"
-#include "utils.h"
-#include "relay.h"
 #include "broker.h"
+#include "debug.h"
+#include "relay.h"
+#include "system.h"
 #include "tuya.h"
+#include "utils.h"
 #include "ws.h"
 #include "libs/HeapStats.h"
 
@@ -118,7 +119,7 @@ void setup() {
     setBoardName();
 
     // Show welcome message and system configuration
-    info();
+    info(true);
 
     wifiSetup();
     #if OTA_ARDUINOOTA_SUPPORT

code/espurna/libs/DebugSend.h

@@ -1,47 +0,0 @@
-// -----------------------------------------------------------------------------
-// printf-like debug methods
-// -----------------------------------------------------------------------------
-
-#pragma once
-
-void debugSendImpl(const char*);
-
-void _debugSend(const char * format, va_list args) {
-
-    char temp[64];
-    int len = ets_vsnprintf(temp, sizeof(temp), format, args);
-    if (len < 64) { debugSendImpl(temp); return; }
-
-    auto buffer = new char[len + 1];
-    ets_vsnprintf(buffer, len + 1, format, args);
-
-    debugSendImpl(buffer);
-
-    delete[] buffer;
-
-}
-
-void debugSend(const char* format, ...) {
-
-    va_list args;
-    va_start(args, format);
-
-    _debugSend(format, args);
-
-    va_end(args);
-
-}
-
-void debugSend_P(PGM_P format_P, ...) {
-
-    char format[strlen_P(format_P) + 1];
-    memcpy_P(format, format_P, sizeof(format));
-
-    va_list args;
-    va_start(args, format_P);
-
-    _debugSend(format, args);
-
-    va_end(args);
-
-}

code/espurna/terminal.ino

@@ -275,7 +275,7 @@ void _terminalInitCommand() {
     });
 
     terminalRegisterCommand(F("UPTIME"), [](Embedis* e) {
-        DEBUG_MSG_P(PSTR("Uptime: %d seconds\n"), getUptime());
+        infoUptime();
         terminalOK();
     });
 

code/espurna/utils.h

@@ -38,7 +38,8 @@ unsigned long getUptime();
 bool haveRelaysOrSensors();
 
 void infoMemory(const char * name, unsigned int total_memory, unsigned int free_memory);
-void info();
+void infoUptime();
+void info(bool first = false);
 
 bool sslCheckFingerPrint(const char * fingerprint);
 bool sslFingerPrintArray(const char * fingerprint, unsigned char * bytearray);

code/espurna/utils.ino

@@ -207,13 +207,18 @@ namespace Heartbeat {
 
 }
 
-void heartbeat() {
+void infoUptime() {
+    auto uptime [[gnu::unused]] = getUptime();
+    DEBUG_MSG_P(
+        PSTR("Uptime: %02dd %02dh %02dm %02ds\n"),
+        elapsedDays(uptime), numberOfHours(uptime),
+        numberOfMinutes(uptime), numberOfSeconds(uptime)
+    );
+}
 
-    unsigned long uptime_seconds = getUptime();
-    heap_stats_t heap_stats = getHeapStats();
+void heartbeat() {
 
-    UNUSED(uptime_seconds);
-    UNUSED(heap_stats);
+    auto heap_stats [[gnu::unused]] = getHeapStats();
 
     #if MQTT_SUPPORT
         unsigned char _heartbeat_mode = getHeartbeatMode();
@@ -227,7 +232,7 @@ void heartbeat() {
     // -------------------------------------------------------------------------
 
     if (serial) {
-        DEBUG_MSG_P(PSTR("[MAIN] Uptime: %lu seconds\n"), uptime_seconds);
+        infoUptime();
         infoHeapStats();
         #if ADC_MODE_VALUE == ADC_VCC
             DEBUG_MSG_P(PSTR("[MAIN] Power: %lu mV\n"), ESP.getVcc());
@@ -283,7 +288,7 @@ void heartbeat() {
                 mqttSend(MQTT_TOPIC_RSSI, String(WiFi.RSSI()).c_str());
 
             if (hb_cfg & Heartbeat::Uptime)
-                mqttSend(MQTT_TOPIC_UPTIME, String(uptime_seconds).c_str());
+                mqttSend(MQTT_TOPIC_UPTIME, String(getUptime()).c_str());
 
             #if NTP_SUPPORT
                 if ((hb_cfg & Heartbeat::Datetime) && (ntpSynced()))
@@ -335,7 +340,7 @@ void heartbeat() {
 
     #if INFLUXDB_SUPPORT
         if (hb_cfg & Heartbeat::Uptime)
-            idbSend(MQTT_TOPIC_UPTIME, String(uptime_seconds).c_str());
+            idbSend(MQTT_TOPIC_UPTIME, String(getUptime()).c_str());
 
         if (hb_cfg & Heartbeat::Freeheap)
             idbSend(MQTT_TOPIC_FREEHEAP, String(heap_stats.available).c_str());
@@ -418,7 +423,14 @@ const char* _info_wifi_sleep_mode(WiFiSleepType_t type) {
 }
 
 
-void info() {
+void info(bool first) {
+
+    // Avoid printing on early boot when buffering is enabled
+    #if DEBUG_SUPPORT
+
+    #if DEBUG_LOG_BUFFER_SUPPORT
+        if (first && debugLogBuffer()) return;
+    #endif
 
     DEBUG_MSG_P(PSTR("\n\n---8<-------\n\n"));
 
@@ -441,8 +453,7 @@ void info() {
 
     // -------------------------------------------------------------------------
 
-    FlashMode_t mode = ESP.getFlashChipMode();
-    UNUSED(mode);
+    FlashMode_t [[gnu::unused]] mode = ESP.getFlashChipMode();
     DEBUG_MSG_P(PSTR("[MAIN] Flash chip ID: 0x%06X\n"), ESP.getFlashChipId());
     DEBUG_MSG_P(PSTR("[MAIN] Flash speed: %u Hz\n"), ESP.getFlashChipSpeed());
     DEBUG_MSG_P(PSTR("[MAIN] Flash mode: %s\n"), mode == FM_QIO ? "QIO" : mode == FM_QOUT ? "QOUT" : mode == FM_DIO ? "DIO" : mode == FM_DOUT ? "DOUT" : "UNKNOWN");
@@ -485,15 +496,11 @@ void info() {
 
     // -------------------------------------------------------------------------
 
-    static bool show_frag_stats = false;
-
     infoMemory("EEPROM", SPI_FLASH_SEC_SIZE, SPI_FLASH_SEC_SIZE - settingsSize());
-    infoHeapStats(show_frag_stats);
+    infoHeapStats(!first);
     infoMemory("Stack", CONT_STACKSIZE, getFreeStack());
     DEBUG_MSG_P(PSTR("\n"));
 
-    show_frag_stats = true;
-
     // -------------------------------------------------------------------------
 
     DEBUG_MSG_P(PSTR("[MAIN] Boot version: %d\n"), ESP.getBootVersion());
@@ -548,6 +555,8 @@ void info() {
 
     DEBUG_MSG_P(PSTR("\n\n---8<-------\n\n"));
 
+    #endif // DEBUG_SUPPORT == 1
+
 }
 
 // -----------------------------------------------------------------------------