diff --git a/code/espurna/config/dependencies.h b/code/espurna/config/dependencies.h index eb2aa810ba..9a17f15f6e 100644 --- a/code/espurna/config/dependencies.h +++ b/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 diff --git a/code/espurna/config/general.h b/code/espurna/config/general.h index cf72d2dd09..d4422bf4d8 100644 --- a/code/espurna/config/general.h +++ b/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 //------------------------------------------------------------------------------ diff --git a/code/espurna/config/prototypes.h b/code/espurna/config/prototypes.h index 0dc82a58e9..01cda232c4 100644 --- a/code/espurna/config/prototypes.h +++ b/code/espurna/config/prototypes.h @@ -83,20 +83,6 @@ using api_put_callback_f = std::function ; 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: diff --git a/code/espurna/debug.h b/code/espurna/debug.h new file mode 100644 index 0000000000..7a810e572d --- /dev/null +++ b/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(); diff --git a/code/espurna/debug.ino b/code/espurna/debug.ino index a1f0fe1364..cc86491789 100644 --- a/code/espurna/debug.ino +++ b/code/espurna/debug.ino @@ -8,7 +8,10 @@ Copyright (C) 2016-2019 by Xose Pérez #if DEBUG_SUPPORT -#include "libs/DebugSend.h" +#include +#include + +#include "debug.h" #if DEBUG_UDP_SUPPORT #include @@ -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(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 _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::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 diff --git a/code/espurna/espurna.ino b/code/espurna/espurna.ino index 03fe355f95..990e865ea9 100644 --- a/code/espurna/espurna.ino +++ b/code/espurna/espurna.ino @@ -22,11 +22,12 @@ along with this program. If not, see . #include "config/all.h" #include -#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 diff --git a/code/espurna/libs/DebugSend.h b/code/espurna/libs/DebugSend.h deleted file mode 100644 index 11cc52816d..0000000000 --- a/code/espurna/libs/DebugSend.h +++ /dev/null @@ -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); - -} diff --git a/code/espurna/terminal.ino b/code/espurna/terminal.ino index f88534957b..4ab10198b7 100644 --- a/code/espurna/terminal.ino +++ b/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(); }); diff --git a/code/espurna/utils.h b/code/espurna/utils.h index 9b4905ae78..3465f7aa92 100644 --- a/code/espurna/utils.h +++ b/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); diff --git a/code/espurna/utils.ino b/code/espurna/utils.ino index 56f2486a4a..cf486001f9 100644 --- a/code/espurna/utils.ino +++ b/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 + } // -----------------------------------------------------------------------------