Debug: log mode, allow to skip boot messages (#2116)

* debug: log mode, allow to skip boot messages

* typo, fix warning about unhandled switch

* mention telnet wifiserver & reverse changes

code/espurna/config/all.h

@@ -34,7 +34,6 @@
 #include "deprecated.h"
 #include "general.h"
 #include "dependencies.h"
-#include "debug.h"
 #include "prototypes.h"
 #include "sensors.h"
 #include "webui.h"

code/espurna/config/debug.h

@@ -1,17 +0,0 @@
-#pragma once
-
-// -----------------------------------------------------------------------------
-// Debug
-// -----------------------------------------------------------------------------
-
-#define DEBUG_SUPPORT           DEBUG_SERIAL_SUPPORT || DEBUG_UDP_SUPPORT || DEBUG_TELNET_SUPPORT || DEBUG_WEB_SUPPORT
-
-#if DEBUG_SUPPORT
-    #define DEBUG_MSG(...) debugSend(__VA_ARGS__)
-    #define DEBUG_MSG_P(...) debugSend_P(__VA_ARGS__)
-#endif
-
-#ifndef DEBUG_MSG
-    #define DEBUG_MSG(...)
-    #define DEBUG_MSG_P(...)
-#endif

code/espurna/config/dependencies.h

@@ -5,6 +5,8 @@
 // Configuration settings are in the general.h file
 //------------------------------------------------------------------------------
 
+#define DEBUG_SUPPORT               (DEBUG_SERIAL_SUPPORT || DEBUG_UDP_SUPPORT || DEBUG_TELNET_SUPPORT || DEBUG_WEB_SUPPORT)
+
 #if DEBUG_TELNET_SUPPORT
 #undef TELNET_SUPPORT
 #define TELNET_SUPPORT              1
@@ -134,7 +136,7 @@
 #define WEB_SSL_ENABLED          0               // WEB_SUPPORT mode th SSL requires ASYNC_TCP_SSL_ENABLED
 #endif
 
-#if not DEBUG_SUPPORT
+#if !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

code/espurna/config/general.h

@@ -32,6 +32,10 @@
 // DEBUG
 //------------------------------------------------------------------------------
 
+#ifndef DEBUG_LOG_MODE
+#define DEBUG_LOG_MODE          DebugLogMode::ENABLED
+#endif
+
 // Serial debug log
 
 #ifndef DEBUG_SERIAL_SUPPORT

code/espurna/config/progmem.h

@@ -119,7 +119,11 @@ PROGMEM const char espurna_modules[] =
         "SSDP "
     #endif
     #if TELNET_SUPPORT
+    #if TELNET_SERVER == TELNET_SERVER_WIFISERVER
+        "TELNET_SYNC "
+    #else
         "TELNET "
+    #endif // TELNET_SERVER == TELNET_SERVER_WIFISERVER
     #endif
     #if TERMINAL_SUPPORT
         "TERMINAL "

code/espurna/debug.h

@@ -6,16 +6,38 @@ DEBUG MODULE
 
 #pragma once
 
+#include <pgmspace.h>
+
 extern "C" {
-     void custom_crash_callback(struct rst_info*, uint32_t, uint32_t);
+    void custom_crash_callback(struct rst_info*, uint32_t, uint32_t);
 }
 
 class PrintRaw;
 class PrintHex;
 
+enum class DebugLogMode : int {
+    DISABLED = 0,
+    ENABLED = 1,
+    SKIP_BOOT = 2
+};
+
 bool debugLogBuffer();
-void debugSend(const char* format, ...);
-void debugSend_P(PGM_P format_P, ...);
 
 void debugWebSetup();
+void debugConfigure();
+void debugConfigueBoot();
 void debugSetup();
+
+void debugSend(const char* format, ...);
+void debugSend_P(PGM_P format, ...); // PGM_P is `const char*`
+
+#if DEBUG_SUPPORT
+    #define DEBUG_MSG(...) debugSend(__VA_ARGS__)
+    #define DEBUG_MSG_P(...) debugSend_P(__VA_ARGS__)
+#endif
+
+#ifndef DEBUG_MSG
+    #define DEBUG_MSG(...)
+    #define DEBUG_MSG_P(...)
+#endif
+

code/espurna/debug.ino

@@ -9,9 +9,12 @@ Copyright (C) 2016-2019 by Xose Pérez <xose dot perez at gmail dot com>
 #if DEBUG_SUPPORT
 
 #include <limits>
+#include <type_traits>
 #include <vector>
 
 #include "debug.h"
+#include "telnet.h"
+#include "ws.h"
 
 #if DEBUG_UDP_SUPPORT
 #include <WiFiUdp.h>
@@ -21,6 +24,8 @@ char _udp_syslog_header[40] = {0};
 #endif
 #endif
 
+bool _debug_enabled = false;
+
 // -----------------------------------------------------------------------------
 // printf-like debug methods
 // -----------------------------------------------------------------------------
@@ -55,6 +60,8 @@ void _debugSend(const char * format, va_list args) {
 
 void debugSend(const char* format, ...) {
 
+    if (!_debug_enabled) return;
+
     va_list args;
     va_start(args, format);
 
@@ -64,7 +71,9 @@ void debugSend(const char* format, ...) {
 
 }
 
-void debugSend_P(PGM_P format_P, ...) {
+void debugSend_P(const char* format_P, ...) {
+
+    if (!_debug_enabled) return;
 
     char format[strlen_P(format_P) + 1];
     memcpy_P(format, format_P, sizeof(format));
@@ -88,20 +97,9 @@ void debugSend_P(PGM_P format_P, ...) {
             DEBUG_PORT.print(prefix);
         }
         DEBUG_PORT.print(data);
-
     }
 #endif // DEBUG_SERIAL_SUPPORT
 
-#if DEBUG_TELNET_SUPPORT
-    void _debugSendTelnet(const char* prefix, const char* data) {
-        if (prefix && (prefix[0] != '\0')) {
-            _telnetWrite(prefix);
-        }
-        _telnetWrite(data);
-
-    }
-#endif // DEBUG_TELNET_SUPPORT
-
 #if DEBUG_LOG_BUFFER_SUPPORT
 
 std::vector<char> _debug_log_buffer;
@@ -129,6 +127,29 @@ void _debugLogBuffer(const char* prefix, const char* data) {
     _debug_log_buffer.insert(_debug_log_buffer.end(), data, data + data_len);
 }
 
+void _debugLogBufferDump() {
+    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();
+}
+
 bool debugLogBuffer() {
     return _debug_log_buffer_enabled;
 }
@@ -165,28 +186,27 @@ void _debugSendInternal(const char * message, bool add_timestamp) {
                 _udp_debug.write(_udp_syslog_header);
             #endif
             _udp_debug.write(message);
-            _udp_debug.endPacket();
-            pause = true;
+            pause = _udp_debug.endPacket() > 0;
         #if SYSTEM_CHECK_ENABLED
         }
         #endif
     #endif
 
     #if DEBUG_TELNET_SUPPORT
-        _debugSendTelnet(timestamp, message);
-        pause = true;
+        pause = telnetDebugSend(timestamp, message) || pause;
     #endif
 
     #if DEBUG_WEB_SUPPORT
-        wsDebugSend(timestamp, message);
-        pause = true;
+        pause = wsDebugSend(timestamp, message) || pause;
     #endif
 
     #if DEBUG_LOG_BUFFER_SUPPORT
         _debugLogBuffer(timestamp, message);
     #endif
 
-    if (pause) optimistic_yield(100);
+    if (pause) {
+        optimistic_yield(1000);
+    }
 
 }
 
@@ -222,7 +242,6 @@ void debugWebSetup() {
     #endif
     #endif
 
-
 }
 
 #endif // DEBUG_WEB_SUPPORT
@@ -235,30 +254,10 @@ void debugSetup() {
         DEBUG_PORT.begin(SERIAL_BAUDRATE);
     #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
-    #if defined(DEBUG_ESP_PORT)
-    #if not defined(NDEBUG)
-        constexpr const bool debug_sdk = true;
-    #endif // !defined(NDEBUG)
-    #else
-        constexpr const bool debug_sdk = false;
-    #endif // defined(DEBUG_ESP_PORT)
-
-    DEBUG_PORT.setDebugOutput(getSetting("dbgSDK", debug_sdk));
+    #if TERMINAL_SUPPORT
 
     #if DEBUG_LOG_BUFFER_SUPPORT
-    {
-        const auto enabled = getSetting("dbgBufEnabled", 1 == DEBUG_LOG_BUFFER_ENABLED);
-        const auto size = getSetting("dbgBufSize", DEBUG_LOG_BUFFER_SIZE);
-        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()) {
@@ -270,29 +269,90 @@ void debugSetup() {
                 _debug_log_buffer.capacity()
             );
 
-            size_t index = 0;
-            do {
-                if (index >= _debug_log_buffer.size()) {
-                    break;
-                }
+            _debugLogBufferDump();
+        });
 
-                size_t len = _debug_log_buffer[index] << 8;
-                len = len | _debug_log_buffer[index + 1];
-                index += 2;
+    #endif // DEBUG_LOG_BUFFER_SUPPORT
 
-                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;
+    #endif // TERMINAL_SUPPORT
 
-                index += len;
-            } while (true);
 
-            _debug_log_buffer.clear();
-            _debug_log_buffer.shrink_to_fit();
-        });
-    #endif // TERMINAL_SUPPORT
+}
+
+String _debugLogModeSerialize(DebugLogMode value) {
+    switch (value) {
+        case DebugLogMode::DISABLED:
+            return "0";
+        case DebugLogMode::SKIP_BOOT:
+            return "2";
+        default:
+        case DebugLogMode::ENABLED:
+            return "1";
+    }
+}
+
+DebugLogMode _debugLogModeDeserialize(const String& value) {
+    switch (value.toInt()) {
+        case 0:
+            return DebugLogMode::DISABLED;
+        case 2:
+            return DebugLogMode::SKIP_BOOT;
+        case 1:
+        default:
+            return DebugLogMode::ENABLED;
+    }
+}
+
+void debugConfigureBoot() {
+    static_assert(
+        std::is_same<int, std::underlying_type<DebugLogMode>::type>::value, 
+        "should be able to match DebugLogMode with int"
+    );
+
+    const auto mode = getSetting<DebugLogMode, _debugLogModeDeserialize>("dbgLogMode", DEBUG_LOG_MODE);
+    switch (mode) {
+        case DebugLogMode::SKIP_BOOT:
+            schedule_function([]() {
+                _debug_enabled = true;
+            });
+            // fall through
+        case DebugLogMode::DISABLED:
+            _debug_enabled = false;
+            break;
+        case DebugLogMode::ENABLED:
+            _debug_enabled = true;
+            break;
+    }
+
+    debugConfigure();
+}
 
+void debugConfigure() {
+
+    // HardwareSerial::begin() will automatically enable this when
+    // `#if defined(DEBUG_ESP_PORT) && !defined(NDEBUG)`
+    // Core debugging also depends on various DEBUG_ESP_... being defined
+    {
+        #if defined(DEBUG_ESP_PORT)
+        #if not defined(NDEBUG)
+            constexpr const bool debug_sdk = true;
+        #endif // !defined(NDEBUG)
+        #else
+            constexpr const bool debug_sdk = false;
+        #endif // defined(DEBUG_ESP_PORT)
+
+        DEBUG_PORT.setDebugOutput(getSetting("dbgSDK", debug_sdk));
+    }
+
+    #if DEBUG_LOG_BUFFER_SUPPORT
+    {
+        const auto enabled = getSetting("dbgBufEnabled", 1 == DEBUG_LOG_BUFFER_ENABLED);
+        const auto size = getSetting("dbgBufSize", DEBUG_LOG_BUFFER_SIZE);
+        if (enabled) {
+            _debug_log_buffer_enabled = true;
+            _debug_log_buffer.reserve(size);
+        }
+    }
     #endif // DEBUG_LOG_BUFFER
 
 }

code/espurna/espurna.ino

@@ -80,7 +80,7 @@ void setup() {
     // Cache initial free heap value
     setInitialFreeHeap();
 
-    // Serial debug
+    // Init logging module
     #if DEBUG_SUPPORT
         debugSetup();
     #endif
@@ -97,8 +97,9 @@ void setup() {
     // Init persistance
     settingsSetup();
 
-    // Init crash recorder
+    // Configure logger and crash recorder
     #if DEBUG_SUPPORT
+        debugConfigureBoot();
         crashSetup();
     #endif
 

code/espurna/telnet.h

@@ -0,0 +1,61 @@
+/*
+
+TELNET MODULE
+
+Copyright (C) 2017-2019 by Xose Pérez <xose dot perez at gmail dot com>
+
+*/
+
+#pragma once
+
+#include <memory>
+#include <list>
+
+#include <Schedule.h>
+
+#include <ESP8266WiFi.h>
+#include <ESPAsyncTCP.h>
+
+struct AsyncBufferedClient {
+    public:
+        constexpr static const size_t BUFFERS_MAX = 5;
+        using buffer_t = std::vector<uint8_t>;
+
+        AsyncBufferedClient(AsyncClient* client);
+
+        size_t write(char c);
+        size_t write(const char* data, size_t size=0);
+
+        void flush();
+        size_t available();
+
+        bool connect(const char *host, uint16_t port);
+        void close(bool now = false);
+        bool connected();
+
+    private:
+        void _addBuffer();
+
+        static void _trySend(AsyncBufferedClient* client);
+        static void _s_onAck(void* client_ptr, AsyncClient*, size_t, uint32_t);
+        static void _s_onPoll(void* client_ptr, AsyncClient* client);
+
+        std::unique_ptr<AsyncClient> _client;
+        std::list<buffer_t> _buffers;
+};
+
+#if TELNET_SERVER == TELNET_SERVER_WIFISERVER
+    using TTelnetServer = WiFiServer;
+    using TTelnetClient = WiFiClient;
+#elif TELNET_SERVER == TELNET_SERVER_ASYNC
+    using TTelnetServer = AsyncServer;
+#if TELNET_SERVER_ASYNC_BUFFERED
+    using TTelnetClient = AsyncBufferedClient;
+#else
+    using TTelnetClient = AsyncClient;
+#endif // TELNET_SERVER_ASYNC_BUFFERED
+#endif
+
+constexpr const char TELNET_IAC = 0xFF;
+constexpr const char TELNET_XEOF = 0xEC;
+

code/espurna/telnet.ino

@@ -9,65 +9,16 @@ Parts of the code have been borrowed from Thomas Sarlandie's NetServer
 
 AsyncBufferedClient based on ESPAsyncTCPbuffer, distributed with the ESPAsyncTCP
 (https://github.com/me-no-dev/ESPAsyncTCP/blob/master/src/ESPAsyncTCPbuffer.cpp)
+Copyright (C) 2019-2020 by Maxim Prokhorov <prokhorov dot max at outlook dot com>
+
+Updated to use WiFiServer and support reverse connections by Niek van der Maas < mail at niekvandermaas dot nl>
 
 */
 
 #if TELNET_SUPPORT
 
-#define TELNET_IAC  0xFF
-#define TELNET_XEOF 0xEC
-
-#if TELNET_SERVER == TELNET_SERVER_WIFISERVER
-    using TTelnetServer = WiFiServer;
-    using TTelnetClient = WiFiClient;
-
-#elif TELNET_SERVER == TELNET_SERVER_ASYNC
-    #include <ESPAsyncTCP.h>
-    #include <Schedule.h>
-    using TTelnetServer = AsyncServer;
-
-#if TELNET_SERVER_ASYNC_BUFFERED
-    #include <list>
-
-    struct AsyncBufferedClient {
-        constexpr static const size_t BUFFERS_MAX = 5;
-        using buffer_t = std::vector<uint8_t>;
-
-        AsyncBufferedClient(AsyncClient* client) :
-            _client(client)
-        {
-            _client->onAck(_s_onAck, this);
-            _client->onPoll(_s_onPoll, this);
-        }
-
-        void _addBuffer();
-        static void _trySend(AsyncBufferedClient* client);
-        static void _s_onAck(void* client_ptr, AsyncClient*, size_t, uint32_t);
-        static void _s_onPoll(void* client_ptr, AsyncClient* client);
-
-        size_t write(char c);
-        size_t write(const char* data, size_t size=0);
-
-        void flush();
-        size_t available();
-
-        bool connect(const char *host, uint16_t port);
-        void close(bool now = false);
-        bool connected();
-
-        std::unique_ptr<AsyncClient> _client;
-
-        std::list<buffer_t> _buffers;
-    };
-
-    using TTelnetClient = AsyncBufferedClient;
-
-#else
-    using TTelnetClient = AsyncClient;
-
-#endif // TELNET_SERVER_ASYNC_BUFFERED
-
-#endif // TELNET_SERVER == TELNET_SERVER_WIFISERVER
+#include <memory>
+#include "telnet.h"
 
 TTelnetServer _telnetServer(TELNET_PORT);
 std::unique_ptr<TTelnetClient> _telnetClients[TELNET_MAX_CLIENTS];
@@ -180,6 +131,11 @@ void _telnetDisconnect(unsigned char clientId) {
 
 #if TELNET_SERVER_ASYNC_BUFFERED
 
+AsyncBufferedClient::AsyncBufferedClient(AsyncClient* client) : _client(client) {
+    _client->onAck(_s_onAck, this);
+    _client->onPoll(_s_onPoll, this);
+}
+
 void AsyncBufferedClient::_trySend(AsyncBufferedClient* client) {
     while (!client->_buffers.empty()) {
         auto& chunk = client->_buffers.front();
@@ -496,12 +452,25 @@ void _telnetNewClient(AsyncClient* client) {
 // -----------------------------------------------------------------------------
 
 bool telnetConnected() {
-    for (unsigned char i = 0; i < TELNET_MAX_CLIENTS; i++) {
-        if (_telnetClients[i] && _telnetClients[i]->connected()) return true;
+    for (auto& client : _telnetClients) {
+        if (client && client->connected()) return true;
     }
     return false;
 }
 
+#if DEBUG_TELNET_SUPPORT
+
+bool telnetDebugSend(const char* prefix, const char* data) {
+    if (!telnetConnected()) return false;
+    bool result = false;
+    if (prefix && (prefix[0] != '\0')) {
+        result = _telnetWrite(prefix) > 0;
+    }
+    return (_telnetWrite(data) > 0) || result;
+}
+
+#endif // DEBUG_TELNET_SUPPORT
+
 unsigned char telnetWrite(unsigned char ch) {
     char data[1] = {ch};
     return _telnetWrite(data, 1);
@@ -512,6 +481,7 @@ void _telnetConfigure() {
 }
 
 void telnetSetup() {
+
     #if TELNET_SERVER == TELNET_SERVER_WIFISERVER
         espurnaRegisterLoop(_telnetLoop);
         _telnetServer.setNoDelay(true);
@@ -519,7 +489,7 @@ void telnetSetup() {
     #else
         _telnetServer.onClient([](void *s, AsyncClient* c) {
             _telnetNewClient(c);
-        }, 0);
+        }, nullptr);
         _telnetServer.begin();
     #endif
 
@@ -554,9 +524,7 @@ void telnetSetup() {
     espurnaRegisterReload(_telnetConfigure);
     _telnetConfigure();
 
-    DEBUG_MSG_P(PSTR("[TELNET] %s server, Listening on port %d\n"),
-        (TELNET_SERVER == TELNET_SERVER_WIFISERVER) ? "Sync" : "Async",
-        TELNET_PORT);
+    DEBUG_MSG_P(PSTR("[TELNET] Listening on port %d\n"), TELNET_PORT);
 
 }
 

code/espurna/utils.ino

@@ -423,6 +423,7 @@ void info(bool first) {
     // -------------------------------------------------------------------------
 
     FlashMode_t mode [[gnu::unused]] = 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");
@@ -498,7 +499,10 @@ void info(bool first) {
 
     // -------------------------------------------------------------------------
 
-    DEBUG_MSG_P(PSTR("[MAIN] Firmware MD5: %s\n"), (char *) ESP.getSketchMD5().c_str());
+    if (!first) {
+        DEBUG_MSG_P(PSTR("[MAIN] Firmware MD5: %s\n"), (char *) ESP.getSketchMD5().c_str());
+    }
+
     #if ADC_MODE_VALUE == ADC_VCC
         DEBUG_MSG_P(PSTR("[MAIN] Power: %u mV\n"), ESP.getVcc());
     #endif