diff --git a/esphome/components/logger/logger.cpp b/esphome/components/logger/logger.cpp index 637a816b6e7..5dfe77a7c93 100644 --- a/esphome/components/logger/logger.cpp +++ b/esphome/components/logger/logger.cpp @@ -205,14 +205,13 @@ void Logger::process_messages_() { } #ifdef USE_LOGGER_BOOT_LOG_BUFFER -// Record layout in boot_log_buffer_: u16 text_len | u8 level | u32 millis | text -static constexpr uint16_t BOOT_LOG_RECORD_HEADER_SIZE = 7; +// Record layout in boot_log_buffer_: u16 text_len | u8 level | u32 millis | const char *tag | text +static constexpr uint16_t BOOT_LOG_RECORD_HEADER_SIZE = 2 + 1 + 4 + sizeof(const char *); -void Logger::boot_log_capture_(uint8_t level, const LogBuffer &buf) { +void Logger::boot_log_capture_(uint8_t level, const char *tag, const LogBuffer &buf) { if (this->boot_log_done_ || level > ESPHOME_LOG_LEVEL_WARN || level == ESPHOME_LOG_LEVEL_NONE) return; - // Strip the leading ANSI color prefix and trailing reset; the replay re-emits - // the text through the normal formatter, which colors it again. + // Strip the leading ANSI color prefix and trailing reset; the replay adds its own around the stamp. const char *text = buf.data; uint16_t len = buf.pos; if (len > 0 && text[0] == '\033') { @@ -234,6 +233,7 @@ void Logger::boot_log_capture_(uint8_t level, const LogBuffer &buf) { memcpy(p, &len, sizeof(len)); p[2] = static_cast(level); memcpy(p + 3, &now, sizeof(now)); + memcpy(p + 7, &tag, sizeof(tag)); // tags are string literals, so the pointer stays valid memcpy(p + BOOT_LOG_RECORD_HEADER_SIZE, text, len); this->boot_log_pos_ += BOOT_LOG_RECORD_HEADER_SIZE + len; } @@ -247,11 +247,24 @@ void Logger::replay_boot_logs() { const char *p = this->boot_log_buffer_ + pos; uint16_t len; memcpy(&len, p, sizeof(len)); + const auto level = static_cast(p[2]); uint32_t stamp; memcpy(&stamp, p + 3, sizeof(stamp)); - esp_log_printf_(static_cast(p[2]), TAG, __LINE__, ESPHOME_LOG_FORMAT("@%" PRIu32 "ms %.*s"), stamp, - static_cast(len), p + BOOT_LOG_RECORD_HEADER_SIZE); + const char *tag; + memcpy(&tag, p + 7, sizeof(tag)); pos += BOOT_LOG_RECORD_HEADER_SIZE + len; + if (level > this->level_for(tag)) + continue; + // The stored text already carries its [LEVEL][tag:line] header, so write the + // line straight to the listeners instead of formatting it a second time. + LogBuffer buf{this->tx_buffer_, ESPHOME_LOGGER_TX_BUFFER_SIZE}; + const int written = snprintf( + buf.data, buf.size, "\033[%c;3%cm@%" PRIu32 "ms ", level == ESPHOME_LOG_LEVEL_ERROR ? '1' : '0', + static_cast(progmem_read_byte(reinterpret_cast(&LOG_LEVEL_COLOR_DIGIT[level]))), stamp); + buf.pos = static_cast(written); + buf.write_body(p + BOOT_LOG_RECORD_HEADER_SIZE, len); + this->notify_listeners_(level, tag, buf); + this->write_log_buffer_to_console_(buf); } ESP_LOGI(TAG, "Boot log replay done"); } diff --git a/esphome/components/logger/logger.h b/esphome/components/logger/logger.h index ade5ff1bcf2..1a0ba84f9fe 100644 --- a/esphome/components/logger/logger.h +++ b/esphome/components/logger/logger.h @@ -303,7 +303,7 @@ class Logger final : public Component { this->format_log_to_buffer_with_terminator_(level, tag, line, format, args, buf, thread_name); } #ifdef USE_LOGGER_BOOT_LOG_BUFFER - this->boot_log_capture_(level, buf); + this->boot_log_capture_(level, tag, buf); #endif this->notify_listeners_(level, tag, buf); this->write_log_buffer_to_console_(buf); @@ -318,7 +318,7 @@ class Logger final : public Component { buf.write_header(level, tag, line, thread_name); buf.write_body(text, text_length); #ifdef USE_LOGGER_BOOT_LOG_BUFFER - this->boot_log_capture_(level, buf); + this->boot_log_capture_(level, tag, buf); #endif this->notify_listeners_(level, tag, buf); } @@ -329,8 +329,8 @@ class Logger final : public Component { #endif #ifdef USE_LOGGER_BOOT_LOG_BUFFER - /// Copy a formatted WARN/ERROR line (ANSI codes stripped) into the boot log buffer. - void boot_log_capture_(uint8_t level, const LogBuffer &buf); + /// Copy a formatted WARN/ERROR line (outer ANSI codes stripped) into the boot log buffer. + void boot_log_capture_(uint8_t level, const char *tag, const LogBuffer &buf); #endif // Group 4-byte aligned members first @@ -396,7 +396,7 @@ class Logger final : public Component { // Large buffers placed last to keep frequently-accessed member offsets small char tx_buffer_[ESPHOME_LOGGER_TX_BUFFER_SIZE + 1]; // +1 for null terminator #ifdef USE_LOGGER_BOOT_LOG_BUFFER - // Sequential records of early WARN/ERROR lines: u16 text_len | u8 level | u32 millis | text + // Sequential records of early WARN/ERROR lines: u16 text_len | u8 level | u32 millis | const char *tag | text char boot_log_buffer_[ESPHOME_LOGGER_BOOT_LOG_BUFFER_SIZE]; #endif #ifdef USE_ESPHOME_TASK_LOG_BUFFER diff --git a/tests/components/logger/__init__.py b/tests/components/logger/__init__.py index 3acfe02748c..30073095c26 100644 --- a/tests/components/logger/__init__.py +++ b/tests/components/logger/__init__.py @@ -1,3 +1,6 @@ +import esphome.codegen as cg +from esphome.components.logger import request_log_listener +from esphome.types import ConfigType from tests.testing_helpers import ComponentManifestOverride @@ -5,3 +8,15 @@ def override_manifest(manifest: ComponentManifestOverride) -> None: # logger must run its to_code during C++ test builds because it configures # the logging subsystem used by ESP_LOG* macros throughout component code. manifest.enable_codegen() + + original_to_code = manifest.to_code + + async def to_code(config: ConfigType) -> None: + await original_to_code(config) + # The boot log buffer is off by default; the host tests exercise it and + # read the replay through a log listener, which nothing else registers here. + cg.add_define("USE_LOGGER_BOOT_LOG_BUFFER") + cg.add_define("ESPHOME_LOGGER_BOOT_LOG_BUFFER_SIZE", 512) + request_log_listener() + + manifest.to_code = to_code diff --git a/tests/components/logger/boot_log_buffer_test.cpp b/tests/components/logger/boot_log_buffer_test.cpp new file mode 100644 index 00000000000..e7f2b0f1450 --- /dev/null +++ b/tests/components/logger/boot_log_buffer_test.cpp @@ -0,0 +1,102 @@ +#include + +#include +#include + +#include "esphome/components/logger/logger.h" +#include "esphome/core/log.h" + +namespace esphome::logger::testing { + +ESPHOME_LOG_TAG(BOOT_TAG, "boot.test"); + +struct Captured { + uint8_t level; + const char *tag; + std::string message; +}; + +// Collects what a listener such as the API connection would receive. +static void capture(void *instance, uint8_t level, const char *tag, const char *message, size_t len) { + static_cast *>(instance)->push_back({level, tag, std::string(message, len)}); +} + +class BootLogBufferTest : public ::testing::Test { + protected: + void SetUp() override { + this->previous_ = global_logger; + this->logger_ = new Logger(0); // NOLINT: freed in TearDown, Logger is not movable + this->logger_->pre_setup(); + this->logger_->set_log_level(ESPHOME_LOG_LEVEL_DEBUG); + } + void TearDown() override { + delete this->logger_; + global_logger = this->previous_; + } + void listen() { this->logger_->add_log_callback(&this->lines_, capture); } + std::vector replayed() const { + std::vector out; + for (const auto &line : this->lines_) { + if (line.message.find("@") != std::string::npos && line.message.find("ms ") != std::string::npos) + out.push_back(line); + } + return out; + } + + Logger *logger_{nullptr}; + Logger *previous_{nullptr}; + std::vector lines_; +}; + +TEST_F(BootLogBufferTest, ReplaysWarningsAndErrorsWithTheirTagAndLevel) { + ESP_LOGW(BOOT_TAG, "early warning %d", 1); + ESP_LOGE(BOOT_TAG, "early error"); + ESP_LOGI(BOOT_TAG, "info is not kept"); + + this->listen(); + this->logger_->replay_boot_logs(); + + const auto lines = this->replayed(); + ASSERT_EQ(lines.size(), 2u); + EXPECT_EQ(lines[0].level, ESPHOME_LOG_LEVEL_WARN); + EXPECT_EQ(lines[0].tag, BOOT_TAG); + EXPECT_NE(lines[0].message.find("[W][boot.test:"), std::string::npos) << lines[0].message; + EXPECT_NE(lines[0].message.find("early warning 1"), std::string::npos) << lines[0].message; + EXPECT_EQ(lines[1].level, ESPHOME_LOG_LEVEL_ERROR); + EXPECT_NE(lines[1].message.find("early error"), std::string::npos) << lines[1].message; + // One header per line: the stored header is not formatted a second time + EXPECT_EQ(lines[1].message.find("[E]"), lines[1].message.rfind("[E]")) << lines[1].message; +} + +TEST_F(BootLogBufferTest, ReplayOutputIsNotCapturedAgain) { + ESP_LOGW(BOOT_TAG, "once"); + this->listen(); + this->logger_->replay_boot_logs(); + ESP_LOGW(BOOT_TAG, "after replay"); + this->lines_.clear(); + this->logger_->replay_boot_logs(); + const auto lines = this->replayed(); + ASSERT_EQ(lines.size(), 1u); + EXPECT_NE(lines[0].message.find("once"), std::string::npos) << lines[0].message; +} + +TEST_F(BootLogBufferTest, LinesThatDoNotFitAreCounted) { + for (int i = 0; i < 40; i++) { + ESP_LOGW(BOOT_TAG, "warning number %d padded to make the record longer", i); + } + this->listen(); + this->logger_->replay_boot_logs(); + const auto lines = this->replayed(); + EXPECT_GT(lines.size(), 0u); + EXPECT_LT(lines.size(), 40u); + // The replay summary reports the dropped lines + bool summary = false; + for (const auto &line : this->lines_) { + if (line.message.find("lines dropped") != std::string::npos && + line.message.find(" 0 lines dropped") == std::string::npos) + summary = true; + } + EXPECT_TRUE(summary); +} + +} // namespace esphome::logger::testing diff --git a/tests/components/logger/test-boot_log_buffer.esp32-idf.yaml b/tests/components/logger/test-boot_log_buffer.esp32-idf.yaml index f61c02f1e55..782e9c0e814 100644 --- a/tests/components/logger/test-boot_log_buffer.esp32-idf.yaml +++ b/tests/components/logger/test-boot_log_buffer.esp32-idf.yaml @@ -1,5 +1,3 @@ -<<: !include common-default_uart.yaml - esphome: on_boot: then: diff --git a/tests/components/logger/test-boot_log_buffer.esp8266-ard.yaml b/tests/components/logger/test-boot_log_buffer.esp8266-ard.yaml index 5584d7b8c77..ba51773cdb9 100644 --- a/tests/components/logger/test-boot_log_buffer.esp8266-ard.yaml +++ b/tests/components/logger/test-boot_log_buffer.esp8266-ard.yaml @@ -1,5 +1,3 @@ -<<: !include common-default_uart.yaml - esphome: on_boot: then: