Replay stored lines straight to the listeners with their tag, add host tests

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<char>(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<uint8_t>(p[2]);
     uint32_t stamp;
     memcpy(&stamp, p + 3, sizeof(stamp));
-    esp_log_printf_(static_cast<uint8_t>(p[2]), TAG, __LINE__, ESPHOME_LOG_FORMAT("@%" PRIu32 "ms %.*s"), stamp,
-                    static_cast<int>(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<char>(progmem_read_byte(reinterpret_cast<const uint8_t *>(&LOG_LEVEL_COLOR_DIGIT[level]))), stamp);
+    buf.pos = static_cast<uint16_t>(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");
 }

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

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

tests/components/logger/boot_log_buffer_test.cpp

@@ -0,0 +1,102 @@
+#include <gtest/gtest.h>
+
+#include <string>
+#include <vector>
+
+#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<std::vector<Captured> *>(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<Captured> replayed() const {
+    std::vector<Captured> 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<Captured> 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

tests/components/logger/test-boot_log_buffer.esp32-idf.yaml

@@ -1,5 +1,3 @@
-<<: !include common-default_uart.yaml
-
 esphome:
   on_boot:
     then:

tests/components/logger/test-boot_log_buffer.esp8266-ard.yaml

@@ -1,5 +1,3 @@
-<<: !include common-default_uart.yaml
-
 esphome:
   on_boot:
     then: