sascha/esphome
1
0
Fork 0
mirror of https://github.com/esphome/esphome.git synced 2025-09-24 22:22:22 +01:00
Code Issues Releases Wiki Activity

Fix ESP32 API Disconnects Caused by Concurrent Logger Writes (#8736)

Browse Source 
Co-authored-by: Jesse Hills <3060199+jesserockz@users.noreply.github.com>
This commit is contained in:
J. Nick Koston
2025-05-12 14:03:34 -05:00
committed by GitHub
parent 8324b3244c
commit dded81d622
9 changed files with 533 additions and 133 deletions
Download Patch File Download Diff File Expand all files Collapse all files

197
esphome/components/logger/logger.h
View File

@@ -2,12 +2,19 @@
#include <cstdarg>
#include <map>
#ifdef USE_ESP32
#include <atomic>
#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 <HardwareSerial.h>
@@ -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<void(int, const char *, const char *)> &&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<size_t>(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<std::string, int> log_levels_{};
CallbackManager<void(int, const char *, const char *)> 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<bool> recursion_guard_{false};
#ifdef USE_ESPHOME_TASK_LOG_BUFFER
std::unique_ptr<logger::TaskLogBuffer> log_buffer_; // Will be initialized with init_log_buffer
#endif
#else
bool recursion_guard_{false};
#endif
void *main_task_ = nullptr;
CallbackManager<void(int)> 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)