From 495fa18a27a4739f9752be67f761286c817b0a45 Mon Sep 17 00:00:00 2001 From: Max Prokhorov Date: Tue, 21 Jan 2020 01:48:52 +0300 Subject: [PATCH] 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 | 1 - code/espurna/config/debug.h | 17 --- code/espurna/config/dependencies.h | 4 +- code/espurna/config/general.h | 4 + code/espurna/config/progmem.h | 4 + code/espurna/debug.h | 28 ++++- code/espurna/debug.ino | 178 +++++++++++++++++++---------- code/espurna/espurna.ino | 5 +- code/espurna/telnet.h | 61 ++++++++++ code/espurna/telnet.ino | 88 +++++--------- code/espurna/utils.ino | 6 +- 11 files changed, 252 insertions(+), 144 deletions(-) delete mode 100644 code/espurna/config/debug.h create mode 100644 code/espurna/telnet.h diff --git a/code/espurna/config/all.h b/code/espurna/config/all.h index 35906b69..5f330344 100644 --- a/code/espurna/config/all.h +++ b/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" diff --git a/code/espurna/config/debug.h b/code/espurna/config/debug.h deleted file mode 100644 index 3f70386d..00000000 --- a/code/espurna/config/debug.h +++ /dev/null @@ -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 diff --git a/code/espurna/config/dependencies.h b/code/espurna/config/dependencies.h index 989a65b3..b9da6342 100644 --- a/code/espurna/config/dependencies.h +++ b/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 diff --git a/code/espurna/config/general.h b/code/espurna/config/general.h index c117bb49..837c4490 100644 --- a/code/espurna/config/general.h +++ b/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 diff --git a/code/espurna/config/progmem.h b/code/espurna/config/progmem.h index 41e9601a..18a3315b 100644 --- a/code/espurna/config/progmem.h +++ b/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 " diff --git a/code/espurna/debug.h b/code/espurna/debug.h index 7a810e57..9f742411 100644 --- a/code/espurna/debug.h +++ b/code/espurna/debug.h @@ -6,16 +6,38 @@ DEBUG MODULE #pragma once +#include + 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 + diff --git a/code/espurna/debug.ino b/code/espurna/debug.ino index b7152fc7..cb528b3a 100644 --- a/code/espurna/debug.ino +++ b/code/espurna/debug.ino @@ -9,9 +9,12 @@ Copyright (C) 2016-2019 by Xose Pérez #if DEBUG_SUPPORT #include +#include #include #include "debug.h" +#include "telnet.h" +#include "ws.h" #if DEBUG_UDP_SUPPORT #include @@ -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 _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::type>::value, + "should be able to match DebugLogMode with int" + ); + + const auto mode = getSetting("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 } diff --git a/code/espurna/espurna.ino b/code/espurna/espurna.ino index 712720c4..1424ead0 100644 --- a/code/espurna/espurna.ino +++ b/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 diff --git a/code/espurna/telnet.h b/code/espurna/telnet.h new file mode 100644 index 00000000..f791461e --- /dev/null +++ b/code/espurna/telnet.h @@ -0,0 +1,61 @@ +/* + +TELNET MODULE + +Copyright (C) 2017-2019 by Xose Pérez + +*/ + +#pragma once + +#include +#include + +#include + +#include +#include + +struct AsyncBufferedClient { + public: + constexpr static const size_t BUFFERS_MAX = 5; + using buffer_t = std::vector; + + 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 _client; + std::list _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; + diff --git a/code/espurna/telnet.ino b/code/espurna/telnet.ino index 9a74aa81..be4b8b1c 100644 --- a/code/espurna/telnet.ino +++ b/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 + +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 - #include - using TTelnetServer = AsyncServer; - -#if TELNET_SERVER_ASYNC_BUFFERED - #include - - struct AsyncBufferedClient { - constexpr static const size_t BUFFERS_MAX = 5; - using buffer_t = std::vector; - - 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 _client; - - std::list _buffers; - }; - - using TTelnetClient = AsyncBufferedClient; - -#else - using TTelnetClient = AsyncClient; - -#endif // TELNET_SERVER_ASYNC_BUFFERED - -#endif // TELNET_SERVER == TELNET_SERVER_WIFISERVER +#include +#include "telnet.h" TTelnetServer _telnetServer(TELNET_PORT); std::unique_ptr _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); } diff --git a/code/espurna/utils.ino b/code/espurna/utils.ino index c7345e9c..5f6037d4 100644 --- a/code/espurna/utils.ino +++ b/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