From dded81d6226bfee279a4ba2026f929222ccdc39a Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 12 May 2025 14:03:34 -0500 Subject: [PATCH] Fix ESP32 API Disconnects Caused by Concurrent Logger Writes (#8736) Co-authored-by: Jesse Hills <3060199+jesserockz@users.noreply.github.com> --- esphome/components/logger/__init__.py | 21 ++ esphome/components/logger/logger.cpp | 221 ++++++++++-------- esphome/components/logger/logger.h | 197 +++++++++++++--- esphome/components/logger/task_log_buffer.cpp | 138 +++++++++++ esphome/components/logger/task_log_buffer.h | 69 ++++++ .../test-custom_buffer_size.esp32-idf.yaml | 5 + .../test-disable_log_buffer.esp32-idf.yaml | 5 + .../test-max_buffer_size.esp32-idf.yaml | 5 + .../test-min_buffer_size.esp32-idf.yaml | 5 + 9 files changed, 533 insertions(+), 133 deletions(-) create mode 100644 esphome/components/logger/task_log_buffer.cpp create mode 100644 esphome/components/logger/task_log_buffer.h create mode 100644 tests/components/logger/test-custom_buffer_size.esp32-idf.yaml create mode 100644 tests/components/logger/test-disable_log_buffer.esp32-idf.yaml create mode 100644 tests/components/logger/test-max_buffer_size.esp32-idf.yaml create mode 100644 tests/components/logger/test-min_buffer_size.esp32-idf.yaml diff --git a/esphome/components/logger/__init__.py b/esphome/components/logger/__init__.py index 113f306327..01e75a424d 100644 --- a/esphome/components/logger/__init__.py +++ b/esphome/components/logger/__init__.py @@ -79,6 +79,7 @@ DEFAULT = "DEFAULT" CONF_INITIAL_LEVEL = "initial_level" CONF_LOGGER_ID = "logger_id" +CONF_TASK_LOG_BUFFER_SIZE = "task_log_buffer_size" UART_SELECTION_ESP32 = { VARIANT_ESP32: [UART0, UART1, UART2], @@ -180,6 +181,20 @@ CONFIG_SCHEMA = cv.All( cv.Optional(CONF_BAUD_RATE, default=115200): cv.positive_int, cv.Optional(CONF_TX_BUFFER_SIZE, default=512): cv.validate_bytes, cv.Optional(CONF_DEASSERT_RTS_DTR, default=False): cv.boolean, + cv.SplitDefault( + CONF_TASK_LOG_BUFFER_SIZE, + esp32=768, # Default: 768 bytes (~5-6 messages with 70-byte text plus thread names) + ): cv.All( + cv.only_on_esp32, + cv.validate_bytes, + cv.Any( + cv.int_(0), # Disabled + cv.int_range( + min=640, # Min: ~4-5 messages with 70-byte text plus thread names + max=32768, # Max: Depends on message sizes, typically ~300 messages with default size + ), + ), + ), cv.SplitDefault( CONF_HARDWARE_UART, esp8266=UART0, @@ -238,6 +253,12 @@ async def to_code(config): baud_rate, config[CONF_TX_BUFFER_SIZE], ) + if CORE.is_esp32: + task_log_buffer_size = config[CONF_TASK_LOG_BUFFER_SIZE] + if task_log_buffer_size > 0: + cg.add_define("USE_ESPHOME_TASK_LOG_BUFFER") + cg.add(log.init_log_buffer(task_log_buffer_size)) + cg.add(log.set_log_level(initial_level)) if CONF_HARDWARE_UART in config: cg.add( diff --git a/esphome/components/logger/logger.cpp b/esphome/components/logger/logger.cpp index 57f0ba9f9a..03e42cdd48 100644 --- a/esphome/components/logger/logger.cpp +++ b/esphome/components/logger/logger.cpp @@ -1,5 +1,8 @@ #include "logger.h" #include +#ifdef USE_ESPHOME_TASK_LOG_BUFFER +#include // For unique_ptr +#endif #include "esphome/core/hal.h" #include "esphome/core/log.h" @@ -10,127 +13,118 @@ namespace logger { static const char *const TAG = "logger"; -static const char *const LOG_LEVEL_COLORS[] = { - "", // NONE - ESPHOME_LOG_BOLD(ESPHOME_LOG_COLOR_RED), // ERROR - ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_YELLOW), // WARNING - ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_GREEN), // INFO - ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_MAGENTA), // CONFIG - ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_CYAN), // DEBUG - ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_GRAY), // VERBOSE - ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_WHITE), // VERY_VERBOSE -}; -static const char *const LOG_LEVEL_LETTERS[] = { - "", // NONE - "E", // ERROR - "W", // WARNING - "I", // INFO - "C", // CONFIG - "D", // DEBUG - "V", // VERBOSE - "VV", // VERY_VERBOSE -}; +#ifdef USE_ESP32 +// Implementation for ESP32 (multi-core with atomic support) +// Main thread: synchronous logging with direct buffer access +// Other threads: console output with stack buffer, callbacks via async buffer +void HOT Logger::log_vprintf_(int level, const char *tag, int line, const char *format, va_list args) { // NOLINT + if (level > this->level_for(tag) || recursion_guard_.load(std::memory_order_relaxed)) + return; + recursion_guard_.store(true, std::memory_order_relaxed); -void Logger::write_header_(int level, const char *tag, int line) { - if (level < 0) - level = 0; - if (level > 7) - level = 7; - - const char *color = LOG_LEVEL_COLORS[level]; - const char *letter = LOG_LEVEL_LETTERS[level]; -#if defined(USE_ESP32) || defined(USE_LIBRETINY) TaskHandle_t current_task = xTaskGetCurrentTaskHandle(); -#else - void *current_task = nullptr; -#endif - if (current_task == main_task_) { - this->printf_to_buffer_("%s[%s][%s:%03u]: ", color, letter, tag, line); - } else { - const char *thread_name = ""; // NOLINT(clang-analyzer-deadcode.DeadStores) -#if defined(USE_ESP32) - thread_name = pcTaskGetName(current_task); -#elif defined(USE_LIBRETINY) - thread_name = pcTaskGetTaskName(current_task); -#endif - this->printf_to_buffer_("%s[%s][%s:%03u]%s[%s]%s: ", color, letter, tag, line, - ESPHOME_LOG_BOLD(ESPHOME_LOG_COLOR_RED), thread_name, color); - } -} + // For main task: call log_message_to_buffer_and_send_ which does console and callback logging + if (current_task == main_task_) { + this->log_message_to_buffer_and_send_(level, tag, line, format, args); + recursion_guard_.store(false, std::memory_order_release); + return; + } + + // For non-main tasks: use stack-allocated buffer only for console output + if (this->baud_rate_ > 0) { // If logging is enabled, write to console + // Maximum size for console log messages (includes null terminator) + static const size_t MAX_CONSOLE_LOG_MSG_SIZE = 144; + char console_buffer[MAX_CONSOLE_LOG_MSG_SIZE]; // MUST be stack allocated for thread safety + int buffer_at = 0; // Initialize buffer position + this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, console_buffer, &buffer_at, + MAX_CONSOLE_LOG_MSG_SIZE); + this->write_msg_(console_buffer); + } + +#ifdef USE_ESPHOME_TASK_LOG_BUFFER + // For non-main tasks, queue the message for callbacks - but only if we have any callbacks registered + if (this->log_callback_.size() > 0) { + // This will be processed in the main loop + this->log_buffer_->send_message_thread_safe(static_cast(level), tag, static_cast(line), + current_task, format, args); + } +#endif // USE_ESPHOME_TASK_LOG_BUFFER + + recursion_guard_.store(false, std::memory_order_release); +} +#endif // USE_ESP32 + +#ifndef USE_ESP32 +// Implementation for platforms that do not support atomic operations +// or have to consider logging in other tasks void HOT Logger::log_vprintf_(int level, const char *tag, int line, const char *format, va_list args) { // NOLINT if (level > this->level_for(tag) || recursion_guard_) return; recursion_guard_ = true; - this->reset_buffer_(); - this->write_header_(level, tag, line); - this->vprintf_to_buffer_(format, args); - this->write_footer_(); - this->log_message_(level, tag); + + // Format and send to both console and callbacks + this->log_message_to_buffer_and_send_(level, tag, line, format, args); + recursion_guard_ = false; } +#endif // !USE_ESP32 + #ifdef USE_STORE_LOG_STR_IN_FLASH +// Implementation for ESP8266 with flash string support void Logger::log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format, va_list args) { // NOLINT if (level > this->level_for(tag) || recursion_guard_) return; recursion_guard_ = true; - this->reset_buffer_(); - // copy format string + this->tx_buffer_at_ = 0; + + // Copy format string from progmem auto *format_pgm_p = reinterpret_cast(format); - size_t len = 0; char ch = '.'; - while (!this->is_buffer_full_() && ch != '\0') { + while (this->tx_buffer_at_ < this->tx_buffer_size_ && ch != '\0') { this->tx_buffer_[this->tx_buffer_at_++] = ch = (char) progmem_read_byte(format_pgm_p++); } - // Buffer full form copying format - if (this->is_buffer_full_()) + + // Buffer full from copying format + if (this->tx_buffer_at_ >= this->tx_buffer_size_) return; - // length of format string, includes null terminator - uint32_t offset = this->tx_buffer_at_; + // Save the offset before calling format_log_to_buffer_with_terminator_ + // since it will increment tx_buffer_at_ to the end of the formatted string + uint32_t msg_start = this->tx_buffer_at_; + this->format_log_to_buffer_with_terminator_(level, tag, line, this->tx_buffer_, args, this->tx_buffer_, + &this->tx_buffer_at_, this->tx_buffer_size_); + + // No write console and callback starting at the msg_start + if (this->baud_rate_ > 0) { + this->write_msg_(this->tx_buffer_ + msg_start); + } + this->call_log_callbacks_(level, tag, this->tx_buffer_ + msg_start); - // now apply vsnprintf - this->write_header_(level, tag, line); - this->vprintf_to_buffer_(this->tx_buffer_, args); - this->write_footer_(); - this->log_message_(level, tag, offset); recursion_guard_ = false; } -#endif +#endif // USE_STORE_LOG_STR_IN_FLASH -int HOT Logger::level_for(const char *tag) { - if (this->log_levels_.count(tag) != 0) - return this->log_levels_[tag]; +inline int Logger::level_for(const char *tag) { + auto it = this->log_levels_.find(tag); + if (it != this->log_levels_.end()) + return it->second; return this->current_level_; } -void HOT Logger::log_message_(int level, const char *tag, int offset) { - // remove trailing newline - if (this->tx_buffer_[this->tx_buffer_at_ - 1] == '\n') { - this->tx_buffer_at_--; - } - // make sure null terminator is present - this->set_null_terminator_(); - - const char *msg = this->tx_buffer_ + offset; - - if (this->baud_rate_ > 0) { - this->write_msg_(msg); - } - +void HOT Logger::call_log_callbacks_(int level, const char *tag, const char *msg) { #ifdef USE_ESP32 - // Suppress network-logging if memory constrained, but still log to serial - // ports. In some configurations (eg BLE enabled) there may be some transient + // Suppress network-logging if memory constrained + // In some configurations (eg BLE enabled) there may be some transient // memory exhaustion, and trying to log when OOM can lead to a crash. Skipping // here usually allows the stack to recover instead. // See issue #1234 for analysis. if (xPortGetFreeHeapSize() < 2048) return; #endif - this->log_callback_.call(level, tag, msg); } @@ -141,21 +135,50 @@ Logger::Logger(uint32_t baud_rate, size_t tx_buffer_size) : baud_rate_(baud_rate this->main_task_ = xTaskGetCurrentTaskHandle(); #endif } +#ifdef USE_ESPHOME_TASK_LOG_BUFFER +void Logger::init_log_buffer(size_t total_buffer_size) { + this->log_buffer_ = esphome::make_unique(total_buffer_size); +} +#endif -#ifdef USE_LOGGER_USB_CDC +#if defined(USE_LOGGER_USB_CDC) || defined(USE_ESP32) void Logger::loop() { -#ifdef USE_ARDUINO - if (this->uart_ != UART_SELECTION_USB_CDC) { - return; +#if defined(USE_LOGGER_USB_CDC) && defined(USE_ARDUINO) + if (this->uart_ == UART_SELECTION_USB_CDC) { + static bool opened = false; + if (opened == Serial) { + return; + } + if (false == opened) { + App.schedule_dump_config(); + } + opened = !opened; } - static bool opened = false; - if (opened == Serial) { - return; +#endif + +#ifdef USE_ESPHOME_TASK_LOG_BUFFER + // Process any buffered messages when available + if (this->log_buffer_->has_messages()) { + logger::TaskLogBuffer::LogMessage *message; + const char *text; + void *received_token; + + // Process messages from the buffer + while (this->log_buffer_->borrow_message_main_loop(&message, &text, &received_token)) { + this->tx_buffer_at_ = 0; + // Use the thread name that was stored when the message was created + // This avoids potential crashes if the task no longer exists + const char *thread_name = message->thread_name[0] != '\0' ? message->thread_name : nullptr; + this->write_header_to_buffer_(message->level, message->tag, message->line, thread_name, this->tx_buffer_, + &this->tx_buffer_at_, this->tx_buffer_size_); + this->write_body_to_buffer_(text, message->text_length, this->tx_buffer_, &this->tx_buffer_at_, + this->tx_buffer_size_); + this->write_footer_to_buffer_(this->tx_buffer_, &this->tx_buffer_at_, this->tx_buffer_size_); + this->tx_buffer_[this->tx_buffer_at_] = '\0'; + this->call_log_callbacks_(message->level, message->tag, this->tx_buffer_); + this->log_buffer_->release_message_main_loop(received_token); + } } - if (false == opened) { - App.schedule_dump_config(); - } - opened = !opened; #endif } #endif @@ -171,7 +194,7 @@ void Logger::add_on_log_callback(std::functionlog_callback_.add(std::move(callback)); } float Logger::get_setup_priority() const { return setup_priority::BUS + 500.0f; } -const char *const LOG_LEVELS[] = {"NONE", "ERROR", "WARN", "INFO", "CONFIG", "DEBUG", "VERBOSE", "VERY_VERBOSE"}; +static const char *const LOG_LEVELS[] = {"NONE", "ERROR", "WARN", "INFO", "CONFIG", "DEBUG", "VERBOSE", "VERY_VERBOSE"}; void Logger::dump_config() { ESP_LOGCONFIG(TAG, "Logger:"); @@ -181,12 +204,16 @@ void Logger::dump_config() { ESP_LOGCONFIG(TAG, " Log Baud Rate: %" PRIu32, this->baud_rate_); ESP_LOGCONFIG(TAG, " Hardware UART: %s", get_uart_selection_()); #endif +#ifdef USE_ESPHOME_TASK_LOG_BUFFER + if (this->log_buffer_) { + ESP_LOGCONFIG(TAG, " Task Log Buffer Size: %u", this->log_buffer_->size()); + } +#endif for (auto &it : this->log_levels_) { ESP_LOGCONFIG(TAG, " Level for '%s': %s", it.first.c_str(), LOG_LEVELS[it.second]); } } -void Logger::write_footer_() { this->write_to_buffer_(ESPHOME_LOG_RESET_COLOR, strlen(ESPHOME_LOG_RESET_COLOR)); } void Logger::set_log_level(int level) { if (level > ESPHOME_LOG_LEVEL) { diff --git a/esphome/components/logger/logger.h b/esphome/components/logger/logger.h index c4c873e020..8619cc0992 100644 --- a/esphome/components/logger/logger.h +++ b/esphome/components/logger/logger.h @@ -2,12 +2,19 @@ #include #include +#ifdef USE_ESP32 +#include +#endif #include "esphome/core/automation.h" #include "esphome/core/component.h" #include "esphome/core/defines.h" #include "esphome/core/helpers.h" #include "esphome/core/log.h" +#ifdef USE_ESPHOME_TASK_LOG_BUFFER +#include "task_log_buffer.h" +#endif + #ifdef USE_ARDUINO #if defined(USE_ESP8266) || defined(USE_ESP32) #include @@ -26,6 +33,29 @@ namespace esphome { namespace logger { +// Color and letter constants for log levels +static const char *const LOG_LEVEL_COLORS[] = { + "", // NONE + ESPHOME_LOG_BOLD(ESPHOME_LOG_COLOR_RED), // ERROR + ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_YELLOW), // WARNING + ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_GREEN), // INFO + ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_MAGENTA), // CONFIG + ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_CYAN), // DEBUG + ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_GRAY), // VERBOSE + ESPHOME_LOG_COLOR(ESPHOME_LOG_COLOR_WHITE), // VERY_VERBOSE +}; + +static const char *const LOG_LEVEL_LETTERS[] = { + "", // NONE + "E", // ERROR + "W", // WARNING + "I", // INFO + "C", // CONFIG + "D", // DEBUG + "V", // VERBOSE + "VV", // VERY_VERBOSE +}; + #if defined(USE_ESP32) || defined(USE_ESP8266) || defined(USE_RP2040) || defined(USE_LIBRETINY) /** Enum for logging UART selection * @@ -57,7 +87,10 @@ enum UARTSelection { class Logger : public Component { public: explicit Logger(uint32_t baud_rate, size_t tx_buffer_size); -#ifdef USE_LOGGER_USB_CDC +#ifdef USE_ESPHOME_TASK_LOG_BUFFER + void init_log_buffer(size_t total_buffer_size); +#endif +#if defined(USE_LOGGER_USB_CDC) || defined(USE_ESP32) void loop() override; #endif /// Manually set the baud rate for serial, set to 0 to disable. @@ -87,7 +120,7 @@ class Logger : public Component { void pre_setup(); void dump_config() override; - int level_for(const char *tag); + inline int level_for(const char *tag); /// Register a callback that will be called for every log message sent void add_on_log_callback(std::function &&callback); @@ -103,46 +136,66 @@ class Logger : public Component { #endif protected: - void write_header_(int level, const char *tag, int line); - void write_footer_(); - void log_message_(int level, const char *tag, int offset = 0); + void call_log_callbacks_(int level, const char *tag, const char *msg); void write_msg_(const char *msg); - inline bool is_buffer_full_() const { return this->tx_buffer_at_ >= this->tx_buffer_size_; } - inline int buffer_remaining_capacity_() const { return this->tx_buffer_size_ - this->tx_buffer_at_; } - inline void reset_buffer_() { this->tx_buffer_at_ = 0; } - inline void set_null_terminator_() { - // does not increment buffer_at - this->tx_buffer_[this->tx_buffer_at_] = '\0'; - } - inline void write_to_buffer_(char value) { - if (!this->is_buffer_full_()) - this->tx_buffer_[this->tx_buffer_at_++] = value; - } - inline void write_to_buffer_(const char *value, int length) { - for (int i = 0; i < length && !this->is_buffer_full_(); i++) { - this->tx_buffer_[this->tx_buffer_at_++] = value[i]; + // Format a log message with printf-style arguments and write it to a buffer with header, footer, and null terminator + // It's the caller's responsibility to initialize buffer_at (typically to 0) + inline void HOT format_log_to_buffer_with_terminator_(int level, const char *tag, int line, const char *format, + va_list args, char *buffer, int *buffer_at, int buffer_size) { +#if defined(USE_ESP32) || defined(USE_LIBRETINY) + this->write_header_to_buffer_(level, tag, line, this->get_thread_name_(), buffer, buffer_at, buffer_size); +#else + this->write_header_to_buffer_(level, tag, line, nullptr, buffer, buffer_at, buffer_size); +#endif + this->format_body_to_buffer_(buffer, buffer_at, buffer_size, format, args); + this->write_footer_to_buffer_(buffer, buffer_at, buffer_size); + + // Always ensure the buffer has a null terminator, even if we need to + // overwrite the last character of the actual content + if (*buffer_at >= buffer_size) { + buffer[buffer_size - 1] = '\0'; // Truncate and ensure null termination + } else { + buffer[*buffer_at] = '\0'; // Normal case, append null terminator } } - inline void vprintf_to_buffer_(const char *format, va_list args) { - if (this->is_buffer_full_()) - return; - int remaining = this->buffer_remaining_capacity_(); - int ret = vsnprintf(this->tx_buffer_ + this->tx_buffer_at_, remaining, format, args); - if (ret < 0) { - // Encoding error, do not increment buffer_at + + // Helper to format and send a log message to both console and callbacks + inline void HOT log_message_to_buffer_and_send_(int level, const char *tag, int line, const char *format, + va_list args) { + // Format to tx_buffer and prepare for output + this->tx_buffer_at_ = 0; // Initialize buffer position + this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, this->tx_buffer_, &this->tx_buffer_at_, + this->tx_buffer_size_); + + if (this->baud_rate_ > 0) { + this->write_msg_(this->tx_buffer_); // If logging is enabled, write to console + } + this->call_log_callbacks_(level, tag, this->tx_buffer_); + } + + // Write the body of the log message to the buffer + inline void write_body_to_buffer_(const char *value, size_t length, char *buffer, int *buffer_at, int buffer_size) { + // Calculate available space + const int available = buffer_size - *buffer_at; + if (available <= 0) return; + + // Determine copy length (minimum of remaining capacity and string length) + const size_t copy_len = (length < static_cast(available)) ? length : available; + + // Copy the data + if (copy_len > 0) { + memcpy(buffer + *buffer_at, value, copy_len); + *buffer_at += copy_len; } - if (ret >= remaining) { - // output was too long, truncated - ret = remaining; - } - this->tx_buffer_at_ += ret; } - inline void printf_to_buffer_(const char *format, ...) { + + // Format string to explicit buffer with varargs + inline void printf_to_buffer_(const char *format, char *buffer, int *buffer_at, int buffer_size, ...) { va_list arg; - va_start(arg, format); - this->vprintf_to_buffer_(format, arg); + va_start(arg, buffer_size); + this->format_body_to_buffer_(buffer, buffer_at, buffer_size, format, arg); va_end(arg); } @@ -169,10 +222,82 @@ class Logger : public Component { std::map log_levels_{}; CallbackManager log_callback_{}; int current_level_{ESPHOME_LOG_LEVEL_VERY_VERBOSE}; - /// Prevents recursive log calls, if true a log message is already being processed. - bool recursion_guard_ = false; +#ifdef USE_ESP32 + std::atomic recursion_guard_{false}; +#ifdef USE_ESPHOME_TASK_LOG_BUFFER + std::unique_ptr log_buffer_; // Will be initialized with init_log_buffer +#endif +#else + bool recursion_guard_{false}; +#endif void *main_task_ = nullptr; CallbackManager level_callback_{}; + +#if defined(USE_ESP32) || defined(USE_LIBRETINY) + const char *HOT get_thread_name_() { + TaskHandle_t current_task = xTaskGetCurrentTaskHandle(); + if (current_task == main_task_) { + return nullptr; // Main task + } else { +#if defined(USE_ESP32) + return pcTaskGetName(current_task); +#elif defined(USE_LIBRETINY) + return pcTaskGetTaskName(current_task); +#endif + } + } +#endif + + inline void HOT write_header_to_buffer_(int level, const char *tag, int line, const char *thread_name, char *buffer, + int *buffer_at, int buffer_size) { + // Format header + if (level < 0) + level = 0; + if (level > 7) + level = 7; + + const char *color = esphome::logger::LOG_LEVEL_COLORS[level]; + const char *letter = esphome::logger::LOG_LEVEL_LETTERS[level]; + +#if defined(USE_ESP32) || defined(USE_LIBRETINY) + if (thread_name != nullptr) { + // Non-main task with thread name + this->printf_to_buffer_("%s[%s][%s:%03u]%s[%s]%s: ", buffer, buffer_at, buffer_size, color, letter, tag, line, + ESPHOME_LOG_BOLD(ESPHOME_LOG_COLOR_RED), thread_name, color); + return; + } +#endif + // Main task or non ESP32/LibreTiny platform + this->printf_to_buffer_("%s[%s][%s:%03u]: ", buffer, buffer_at, buffer_size, color, letter, tag, line); + } + + inline void HOT format_body_to_buffer_(char *buffer, int *buffer_at, int buffer_size, const char *format, + va_list args) { + // Get remaining capacity in the buffer + const int remaining = buffer_size - *buffer_at; + if (remaining <= 0) + return; + + const int ret = vsnprintf(buffer + *buffer_at, remaining, format, args); + + if (ret < 0) { + return; // Encoding error, do not increment buffer_at + } + + // Update buffer_at with the formatted length (handle truncation) + int formatted_len = (ret >= remaining) ? remaining : ret; + *buffer_at += formatted_len; + + // Remove all trailing newlines right after formatting + while (*buffer_at > 0 && buffer[*buffer_at - 1] == '\n') { + (*buffer_at)--; + } + } + + inline void HOT write_footer_to_buffer_(char *buffer, int *buffer_at, int buffer_size) { + static const int RESET_COLOR_LEN = strlen(ESPHOME_LOG_RESET_COLOR); + this->write_body_to_buffer_(ESPHOME_LOG_RESET_COLOR, RESET_COLOR_LEN, buffer, buffer_at, buffer_size); + } }; extern Logger *global_logger; // NOLINT(cppcoreguidelines-avoid-non-const-global-variables) diff --git a/esphome/components/logger/task_log_buffer.cpp b/esphome/components/logger/task_log_buffer.cpp new file mode 100644 index 0000000000..24d9284f1a --- /dev/null +++ b/esphome/components/logger/task_log_buffer.cpp @@ -0,0 +1,138 @@ + +#include "task_log_buffer.h" +#include "esphome/core/helpers.h" +#include "esphome/core/log.h" + +#ifdef USE_ESPHOME_TASK_LOG_BUFFER + +namespace esphome { +namespace logger { + +TaskLogBuffer::TaskLogBuffer(size_t total_buffer_size) { + // Store the buffer size + this->size_ = total_buffer_size; + // Allocate memory for the ring buffer using ESPHome's RAM allocator + RAMAllocator allocator; + this->storage_ = allocator.allocate(this->size_); + // Create a static ring buffer with RINGBUF_TYPE_NOSPLIT for message integrity + this->ring_buffer_ = xRingbufferCreateStatic(this->size_, RINGBUF_TYPE_NOSPLIT, this->storage_, &this->structure_); +} + +TaskLogBuffer::~TaskLogBuffer() { + if (this->ring_buffer_ != nullptr) { + // Delete the ring buffer + vRingbufferDelete(this->ring_buffer_); + this->ring_buffer_ = nullptr; + + // Free the allocated memory + RAMAllocator allocator; + allocator.deallocate(this->storage_, this->size_); + this->storage_ = nullptr; + } +} + +bool TaskLogBuffer::borrow_message_main_loop(LogMessage **message, const char **text, void **received_token) { + if (message == nullptr || text == nullptr || received_token == nullptr) { + return false; + } + + size_t item_size = 0; + void *received_item = xRingbufferReceive(ring_buffer_, &item_size, 0); + if (received_item == nullptr) { + return false; + } + + LogMessage *msg = static_cast(received_item); + *message = msg; + *text = msg->text_data(); + *received_token = received_item; + + return true; +} + +void TaskLogBuffer::release_message_main_loop(void *token) { + if (token == nullptr) { + return; + } + vRingbufferReturnItem(ring_buffer_, token); + // Update counter to mark all messages as processed + last_processed_counter_ = message_counter_.load(std::memory_order_relaxed); +} + +bool TaskLogBuffer::send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, TaskHandle_t task_handle, + const char *format, va_list args) { + // First, calculate the exact length needed using a null buffer (no actual writing) + va_list args_copy; + va_copy(args_copy, args); + int ret = vsnprintf(nullptr, 0, format, args_copy); + va_end(args_copy); + + if (ret <= 0) { + return false; // Formatting error or empty message + } + + // Calculate actual text length (capped to maximum size) + static constexpr size_t MAX_TEXT_SIZE = 255; + size_t text_length = (static_cast(ret) > MAX_TEXT_SIZE) ? MAX_TEXT_SIZE : ret; + + // Calculate total size needed (header + text length + null terminator) + size_t total_size = sizeof(LogMessage) + text_length + 1; + + // Acquire memory directly from the ring buffer + void *acquired_memory = nullptr; + BaseType_t result = xRingbufferSendAcquire(ring_buffer_, &acquired_memory, total_size, 0); + + if (result != pdTRUE || acquired_memory == nullptr) { + return false; // Failed to acquire memory + } + + // Set up the message header in the acquired memory + LogMessage *msg = static_cast(acquired_memory); + msg->level = level; + msg->tag = tag; + msg->line = line; + + // Store the thread name now instead of waiting until main loop processing + // This avoids crashes if the task completes or is deleted between when this message + // is enqueued and when it's processed by the main loop + const char *thread_name = pcTaskGetName(task_handle); + if (thread_name != nullptr) { + strncpy(msg->thread_name, thread_name, sizeof(msg->thread_name) - 1); + msg->thread_name[sizeof(msg->thread_name) - 1] = '\0'; // Ensure null termination + } else { + msg->thread_name[0] = '\0'; // Empty string if no thread name + } + + // Format the message text directly into the acquired memory + // We add 1 to text_length to ensure space for null terminator during formatting + char *text_area = msg->text_data(); + ret = vsnprintf(text_area, text_length + 1, format, args); + + // Handle unexpected formatting error + if (ret <= 0) { + vRingbufferReturnItem(ring_buffer_, acquired_memory); + return false; + } + + // Remove trailing newlines + while (text_length > 0 && text_area[text_length - 1] == '\n') { + text_length--; + } + + msg->text_length = text_length; + // Complete the send operation with the acquired memory + result = xRingbufferSendComplete(ring_buffer_, acquired_memory); + + if (result != pdTRUE) { + return false; // Failed to complete the message send + } + + // Message sent successfully, increment the counter + message_counter_.fetch_add(1, std::memory_order_relaxed); + return true; +} + +} // namespace logger +} // namespace esphome + +#endif // USE_ESPHOME_TASK_LOG_BUFFER diff --git a/esphome/components/logger/task_log_buffer.h b/esphome/components/logger/task_log_buffer.h new file mode 100644 index 0000000000..1618a5a121 --- /dev/null +++ b/esphome/components/logger/task_log_buffer.h @@ -0,0 +1,69 @@ +#pragma once + +#include "esphome/core/defines.h" +#include "esphome/core/helpers.h" + +#ifdef USE_ESPHOME_TASK_LOG_BUFFER +#include +#include +#include +#include +#include +#include + +namespace esphome { +namespace logger { + +class TaskLogBuffer { + public: + // Structure for a log message header (text data follows immediately after) + struct LogMessage { + const char *tag; // We store the pointer, assuming tags are static + char thread_name[16]; // Store thread name directly (only used for non-main threads) + uint16_t text_length; // Length of the message text (up to ~64KB) + uint16_t line; // Source code line number + uint8_t level; // Log level (0-7) + + // Methods for accessing message contents + inline char *text_data() { return reinterpret_cast(this) + sizeof(LogMessage); } + + inline const char *text_data() const { return reinterpret_cast(this) + sizeof(LogMessage); } + }; + + // Constructor that takes a total buffer size + explicit TaskLogBuffer(size_t total_buffer_size); + ~TaskLogBuffer(); + + // NOT thread-safe - borrow a message from the ring buffer, only call from main loop + bool borrow_message_main_loop(LogMessage **message, const char **text, void **received_token); + + // NOT thread-safe - release a message buffer and update the counter, only call from main loop + void release_message_main_loop(void *token); + + // Thread-safe - send a message to the ring buffer from any thread + bool send_message_thread_safe(uint8_t level, const char *tag, uint16_t line, TaskHandle_t task_handle, + const char *format, va_list args); + + // Check if there are messages ready to be processed using an atomic counter for performance + inline bool HOT has_messages() const { + return message_counter_.load(std::memory_order_relaxed) != last_processed_counter_; + } + + // Get the total buffer size in bytes + inline size_t size() const { return size_; } + + private: + RingbufHandle_t ring_buffer_{nullptr}; // FreeRTOS ring buffer handle + StaticRingbuffer_t structure_; // Static structure for the ring buffer + uint8_t *storage_{nullptr}; // Pointer to allocated memory + size_t size_{0}; // Size of allocated memory + + // Atomic counter for message tracking (only differences matter) + std::atomic message_counter_{0}; // Incremented when messages are committed + mutable uint16_t last_processed_counter_{0}; // Tracks last processed message +}; + +} // namespace logger +} // namespace esphome + +#endif // USE_ESPHOME_TASK_LOG_BUFFER diff --git a/tests/components/logger/test-custom_buffer_size.esp32-idf.yaml b/tests/components/logger/test-custom_buffer_size.esp32-idf.yaml new file mode 100644 index 0000000000..9a396ca023 --- /dev/null +++ b/tests/components/logger/test-custom_buffer_size.esp32-idf.yaml @@ -0,0 +1,5 @@ +<<: !include common-default_uart.yaml + +logger: + id: logger_id + task_log_buffer_size: 1024B # Set a custom buffer size diff --git a/tests/components/logger/test-disable_log_buffer.esp32-idf.yaml b/tests/components/logger/test-disable_log_buffer.esp32-idf.yaml new file mode 100644 index 0000000000..4260f178f9 --- /dev/null +++ b/tests/components/logger/test-disable_log_buffer.esp32-idf.yaml @@ -0,0 +1,5 @@ +<<: !include common-default_uart.yaml + +logger: + id: logger_id + task_log_buffer_size: 0 diff --git a/tests/components/logger/test-max_buffer_size.esp32-idf.yaml b/tests/components/logger/test-max_buffer_size.esp32-idf.yaml new file mode 100644 index 0000000000..f6c3eae677 --- /dev/null +++ b/tests/components/logger/test-max_buffer_size.esp32-idf.yaml @@ -0,0 +1,5 @@ +<<: !include common-default_uart.yaml + +logger: + id: logger_id + task_log_buffer_size: 32768B # Maximum buffer size diff --git a/tests/components/logger/test-min_buffer_size.esp32-idf.yaml b/tests/components/logger/test-min_buffer_size.esp32-idf.yaml new file mode 100644 index 0000000000..715b0580ed --- /dev/null +++ b/tests/components/logger/test-min_buffer_size.esp32-idf.yaml @@ -0,0 +1,5 @@ +<<: !include common-default_uart.yaml + +logger: + id: logger_id + task_log_buffer_size: 640B # Minimum buffer size with thread names