Florian/esphome
1
0
Fork 0
Code Issues Pull Requests Actions 4 Packages Projects Releases Wiki Activity

Fix ESP32 console logging corruption and message loss in multi-task environments

Browse Source 
These changes enhance ESPHome's logging system on ESP32 multi-task environments:

1. **Emergency Console Logging**:
   - Added fallback console logging when the task log buffer is full or disabled
   - Ensures critical messages are still visible even when the ring buffer fails

2. **Improved Console Output**:
   - Messages successfully sent to the ring buffer now also display on the console
   - Ensures consistent console output for all log messages regardless of source

3. **Optimized Resource Usage**:
   - Release ring buffer messages earlier after transferring to tx_buffer
   - Reduces contention for the shared log buffer in multi-task environments

1. **Stack Memory Efficiency**:
   - No longer need to allocate stack memory for console output when ring buffer is available
   - Only uses stack memory for emergency fallback cases, reducing stack usage in normal operation

2. **Console Output Integrity**:
   - Prevents console output corruption that could occur with concurrent writes from multiple tasks
   - Serializes all console output through the main loop when possible

3. **Message Ordering**:
   - Messages from different tasks may appear slightly out of order due to async delivery to main loop
   - This trade-off is preferable to corrupted console output from concurrent writes

These improvements provide more reliable logging behavior, particularly under memory constraints or high logging volume, while maintaining thread safety and minimizing resource contention.
This commit is contained in:
J. Nick Koston
2025-05-15 10:51:50 -05:00
parent 4761ffe023
commit eebdc9c38f
1 changed files with 30 additions and 14 deletions
Download Patch File Download Diff File Expand all files Collapse all files

44
esphome/components/logger/logger.cpp
View File

@@ -16,9 +16,14 @@ static const char *const TAG = "logger";
#ifdef USE_ESP32
// Implementation for ESP32 (multi-task platform with task-specific tracking)
// Main task always uses direct buffer access for console output and callbacks
// Other tasks:
// - With task log buffer: stack buffer for console output, async buffer for callbacks
// - Without task log buffer: only console output, no callbacks
//
// For non-main tasks:
// - WITH task log buffer: Prefer sending to ring buffer for async processing
// - Avoids allocating stack memory for console output in normal operation
// - Prevents console corruption from concurrent writes by multiple tasks
// - Messages are serialized through main loop for proper console output
// - Fallback to emergency console logging only if ring buffer is full
// - WITHOUT task log buffer: Only emergency console output, no callbacks
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))
return;
@@ -38,8 +43,18 @@ void HOT Logger::log_vprintf_(int level, const char *tag, int line, const char *
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
bool message_sent = false;
#ifdef USE_ESPHOME_TASK_LOG_BUFFER
// For non-main tasks, queue the message for callbacks - but only if we have any callbacks registered
message_sent = this->log_buffer_->send_message_thread_safe(static_cast<uint8_t>(level), tag,
static_cast<uint16_t>(line), current_task, format, args);
#endif // USE_ESPHOME_TASK_LOG_BUFFER
// Emergency console logging for non-main tasks when ring buffer is full or disabled
// This is a fallback mechanism to ensure critical log messages are visible
// Note: This may cause interleaved/corrupted console output if multiple tasks
// log simultaneously, but it's better than losing important messages entirely
if (!message_sent && 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
@@ -49,15 +64,6 @@ void HOT Logger::log_vprintf_(int level, const char *tag, int line, const char *
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<uint8_t>(level), tag, static_cast<uint16_t>(line),
current_task, format, args);
}
#endif // USE_ESPHOME_TASK_LOG_BUFFER
// Reset the recursion guard for this task
this->reset_task_log_recursion_(is_main_task);
}
@@ -184,7 +190,17 @@ void Logger::loop() {
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_);
// At this point all the data we need from message has been transferred to the tx_buffer
// so we can release the message to allow other tasks to use it as soon as possible.
this->log_buffer_->release_message_main_loop(received_token);
// Write to console from the main loop to prevent corruption from concurrent writes
// This ensures all log messages appear on the console in a clean, serialized manner
// Note: Messages may appear slightly out of order due to async processing, but
// this is preferred over corrupted/interleaved console output
if (this->baud_rate_ > 0) {
this->write_msg_(this->tx_buffer_);
}
}
}
#endif