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,21 +100,56 @@ 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);
 
  bool pause = false;
  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