From e57fca4f78c80a07804facd21ff445aa3265dba8 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 13 Oct 2026 10:33:49 -1000 Subject: [PATCH] Guard the replay, warn on dropped lines, cap captured text, and register the action as an apply action --- esphome/components/logger/__init__.py | 24 +++++-------------- esphome/components/logger/logger.cpp | 21 +++++++++++++++- tests/components/logger/__init__.py | 3 +++ .../logger/boot_log_buffer_test.cpp | 15 ++++++++++++ .../test-boot_log_buffer.esp32-idf.yaml | 3 +++ 5 files changed, 47 insertions(+), 19 deletions(-) diff --git a/esphome/components/logger/__init__.py b/esphome/components/logger/__init__.py index f28089bd8f7..f66397e2d8f 100644 --- a/esphome/components/logger/__init__.py +++ b/esphome/components/logger/__init__.py @@ -402,8 +402,9 @@ async def to_code(config: ConfigType) -> None: if (boot_log_buffer_size := config[CONF_BOOT_LOG_BUFFER_SIZE]) > 0: cg.add_define("USE_LOGGER_BOOT_LOG_BUFFER") cg.add_define("ESPHOME_LOGGER_BOOT_LOG_BUFFER_SIZE", boot_log_buffer_size) - cg.add_build_flag( - f"-DESPHOME_LOGGER_BOOT_LOG_LEVEL={LOG_LEVELS[config[CONF_BOOT_LOG_LEVEL]]}" + cg.add_define( + "ESPHOME_LOGGER_BOOT_LOG_LEVEL", + cg.RawExpression(str(LOG_LEVELS[config[CONF_BOOT_LOG_LEVEL]])), ) if boot_logs_config := config[CONF_BOOT_LOGS]: cg.add_define("USE_LOGGER_BOOT_LOG_PER_TAG_LEVELS") @@ -663,30 +664,17 @@ async def logger_set_level_to_code( ) -@automation.register_action( +automation.register_apply_action( "logger.replay_boot_logs", - LambdaAction, automation.maybe_conf( CONF_LOGGER_ID, { cv.GenerateID(CONF_LOGGER_ID): cv.use_id(Logger), }, ), - synchronous=True, + automation.ApplyCall("replay_boot_logs()"), + id_key=CONF_LOGGER_ID, ) -async def logger_replay_boot_logs_to_code( - config: ConfigType, - action_id: ID, - template_arg: cg.TemplateArguments, - args: TemplateArgsType, -) -> MockObj: - logger = await cg.get_variable(config[CONF_LOGGER_ID]) - text = str(cg.statement(logger.replay_boot_logs())) - - lambda_ = await cg.process_lambda(Lambda(text), args, return_type=cg.void) - return automation.new_lambda_pvariable( - action_id, lambda_, StatelessLambdaAction, template_arg - ) FILTER_SOURCE_FILES = filter_source_files_from_platform( diff --git a/esphome/components/logger/logger.cpp b/esphome/components/logger/logger.cpp index 5805d4c0acf..2bec0e15299 100644 --- a/esphome/components/logger/logger.cpp +++ b/esphome/components/logger/logger.cpp @@ -218,6 +218,9 @@ void Logger::process_messages_() { #ifdef USE_LOGGER_BOOT_LOG_BUFFER // 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 *); +// Replay writes "\033[0;3Xm@4294967295ms " (22 bytes) and "\033[0m" (4 bytes) around the stored text +static constexpr uint16_t BOOT_LOG_REPLAY_PREFIX_SIZE = 22; +static constexpr uint16_t BOOT_LOG_MAX_TEXT = ESPHOME_LOGGER_TX_BUFFER_SIZE - BOOT_LOG_REPLAY_PREFIX_SIZE - 4; void Logger::boot_log_capture_(uint8_t level, const char *tag, const LogBuffer &buf) { if (this->boot_log_done_ || level > boot_level_for(tag) || level == ESPHOME_LOG_LEVEL_NONE) @@ -235,6 +238,9 @@ void Logger::boot_log_capture_(uint8_t level, const char *tag, const LogBuffer & } if (len >= 4 && memcmp(text + len - 4, "\033[0m", 4) == 0) len -= 4; + // Leave room in the transmit buffer for the replay prefix and reset so no stored text is cut on replay + if (len > BOOT_LOG_MAX_TEXT) + len = BOOT_LOG_MAX_TEXT; if (this->boot_log_pos_ + BOOT_LOG_RECORD_HEADER_SIZE + len > ESPHOME_LOGGER_BOOT_LOG_BUFFER_SIZE) { this->boot_log_dropped_++; return; @@ -252,7 +258,20 @@ void Logger::boot_log_capture_(uint8_t level, const char *tag, const LogBuffer & void Logger::replay_boot_logs() { // Stop capturing first so the replay output is not buffered again. this->boot_log_done_ = true; - ESP_LOGI(TAG, "Replaying boot logs (%u bytes used, %u lines dropped)", this->boot_log_pos_, this->boot_log_dropped_); + // Dropped lines are reported at WARN so a device at level WARN still learns the buffer was too small + esp_log_printf_(this->boot_log_dropped_ > 0 ? ESPHOME_LOG_LEVEL_WARN : ESPHOME_LOG_LEVEL_INFO, TAG, __LINE__, + ESPHOME_LOG_FORMAT("Replaying boot logs (%u bytes used, %u lines dropped)"), this->boot_log_pos_, + this->boot_log_dropped_); + // The replay shares tx_buffer_ with normal logging, so a listener that logs during + // the replay is dropped like any other re-entrant log; see process_messages_() +#if defined(USE_ESP32) || defined(USE_HOST) || defined(USE_LIBRETINY) || defined(USE_ZEPHYR) + bool &recursion_guard = this->main_task_recursion_guard_; +#else + bool &recursion_guard = this->global_recursion_guard_; +#endif + if (recursion_guard) + return; + RecursionGuard guard(recursion_guard); uint16_t pos = 0; while (pos + BOOT_LOG_RECORD_HEADER_SIZE <= this->boot_log_pos_) { const char *p = this->boot_log_buffer_ + pos; diff --git a/tests/components/logger/__init__.py b/tests/components/logger/__init__.py index 30073095c26..4e3c847fa34 100644 --- a/tests/components/logger/__init__.py +++ b/tests/components/logger/__init__.py @@ -17,6 +17,9 @@ def override_manifest(manifest: ComponentManifestOverride) -> None: # 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) + cg.add_define( + "ESPHOME_LOGGER_BOOT_LOG_LEVEL", cg.RawExpression("ESPHOME_LOG_LEVEL_WARN") + ) 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 index e7f2b0f1450..da3b184264a 100644 --- a/tests/components/logger/boot_log_buffer_test.cpp +++ b/tests/components/logger/boot_log_buffer_test.cpp @@ -99,4 +99,19 @@ TEST_F(BootLogBufferTest, LinesThatDoNotFitAreCounted) { EXPECT_TRUE(summary); } +TEST_F(BootLogBufferTest, LongestLineIsReplayedWithoutLosingItsTail) { + // A line that fills the transmit buffer must still fit once the replay adds its stamp + std::string text(ESPHOME_LOGGER_TX_BUFFER_SIZE, 'x'); + ESP_LOGW(BOOT_TAG, "%s", text.c_str()); + this->listen(); + this->logger_->replay_boot_logs(); + + const auto lines = this->replayed(); + ASSERT_EQ(lines.size(), 1u); + EXPECT_LE(lines[0].message.size(), static_cast(ESPHOME_LOGGER_TX_BUFFER_SIZE)); + // The reset code at the end shows the stored text was not cut short by the prefix + EXPECT_EQ(lines[0].message.substr(lines[0].message.size() - 4), "\033[0m") << lines[0].message.size(); + EXPECT_NE(lines[0].message.find("xxxxxxxxxx\033[0m"), std::string::npos); +} + } // 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 782e9c0e814..bd2aca7dc16 100644 --- a/tests/components/logger/test-boot_log_buffer.esp32-idf.yaml +++ b/tests/components/logger/test-boot_log_buffer.esp32-idf.yaml @@ -9,3 +9,6 @@ esphome: logger: id: logger_id boot_log_buffer_size: 2kB + boot_log_level: INFO + boot_logs: + wifi: DEBUG