From 4d2ef09a296c4fd3e1b5e723024770ab8b8c3339 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 10 Mar 2026 09:12:10 -1000 Subject: [PATCH] [log] Detect early log calls before logger init and optimize hot path (#14538) --- esphome/components/logger/__init__.py | 5 +- esphome/core/application.h | 2 + esphome/core/log.cpp | 60 +++++++++++++------ esphome/core/log.h | 12 +++- script/cpp_unit_test.py | 1 + tests/component_tests/logger/__init__.py | 0 tests/component_tests/logger/test_logger.py | 50 ++++++++++++++++ tests/component_tests/logger/test_logger.yaml | 14 +++++ tests/components/main.cpp | 8 +++ tests/integration/conftest.py | 1 + 10 files changed, 134 insertions(+), 19 deletions(-) create mode 100644 tests/component_tests/logger/__init__.py create mode 100644 tests/component_tests/logger/test_logger.py create mode 100644 tests/component_tests/logger/test_logger.yaml diff --git a/esphome/components/logger/__init__.py b/esphome/components/logger/__init__.py index 83a7854165..e370f4215d 100644 --- a/esphome/components/logger/__init__.py +++ b/esphome/components/logger/__init__.py @@ -337,6 +337,10 @@ async def to_code(config): ) if CORE.is_esp32: cg.add(log.create_pthread_key()) + # pre_setup() must be called before init_log_buffer() because + # init_log_buffer() calls disable_loop() which may log at VV level, + # and global_logger must be set before any logging occurs. + cg.add(log.pre_setup()) if CORE.is_esp32 or CORE.is_libretiny or CORE.is_nrf52: task_log_buffer_size = config[CONF_TASK_LOG_BUFFER_SIZE] if task_log_buffer_size > 0: @@ -356,7 +360,6 @@ async def to_code(config): HARDWARE_UART_TO_UART_SELECTION[config[CONF_HARDWARE_UART]] ) ) - cg.add(log.pre_setup()) # Enable runtime tag levels if logs are configured or explicitly enabled logs_config = config[CONF_LOGS] diff --git a/esphome/core/application.h b/esphome/core/application.h index f357c6b1a3..23bb209eaf 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -142,6 +142,7 @@ static constexpr uint32_t TEARDOWN_TIMEOUT_REBOOT_MS = 1000; // 1 second for qu class Application { public: #ifdef ESPHOME_NAME_ADD_MAC_SUFFIX + // Called before Logger::pre_setup() — must not log (global_logger is not yet set). /// Pre-setup with MAC suffix: overwrites placeholder in mutable static buffers with actual MAC. void pre_setup(char *name, size_t name_len, char *friendly_name, size_t friendly_name_len) { arch_init(); @@ -163,6 +164,7 @@ class Application { this->friendly_name_ = StringRef(friendly_name, friendly_name_len); } #else + // Called before Logger::pre_setup() — must not log (global_logger is not yet set). /// Pre-setup without MAC suffix: StringRef points directly at const string literals in flash. void pre_setup(const char *name, size_t name_len, const char *friendly_name, size_t friendly_name_len) { arch_init(); diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index 8338efbb33..0da457adec 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -1,6 +1,7 @@ #include "log.h" #include "defines.h" #include "helpers.h" +#include #ifdef USE_LOGGER #include "esphome/components/logger/logger.h" @@ -8,40 +9,63 @@ namespace esphome { +#ifdef ESPHOME_DEBUG +static void early_log_printf_(const char *tag, int line, const char *format, va_list args) { + fprintf(stderr, "LOG BEFORE LOGGER INIT [%s:%d]: ", tag, line); + vfprintf(stderr, format, args); + fputc('\n', stderr); + assert(false && "log called before Logger::pre_setup()"); // NOLINT +} +#endif + void HOT esp_log_printf_(int level, const char *tag, int line, const char *format, ...) { // NOLINT +#ifdef USE_LOGGER +#ifdef ESPHOME_DEBUG + if (logger::global_logger == nullptr) { + va_list arg; + va_start(arg, format); + early_log_printf_(tag, line, format, arg); + va_end(arg); + return; + } +#endif va_list arg; va_start(arg, format); - esp_log_vprintf_(level, tag, line, format, arg); + logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, arg); va_end(arg); +#endif } + #ifdef USE_STORE_LOG_STR_IN_FLASH void HOT esp_log_printf_(int level, const char *tag, int line, const __FlashStringHelper *format, ...) { +#ifdef USE_LOGGER + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); va_list arg; va_start(arg, format); - esp_log_vprintf_(level, tag, line, format, arg); + logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, arg); va_end(arg); +#endif } #endif void HOT esp_log_vprintf_(int level, const char *tag, int line, const char *format, va_list args) { // NOLINT #ifdef USE_LOGGER - auto *log = logger::global_logger; - if (log == nullptr) +#ifdef ESPHOME_DEBUG + if (logger::global_logger == nullptr) { + early_log_printf_(tag, line, format, args); return; - - log->log_vprintf_(static_cast(level), tag, line, format, args); + } +#endif + logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, args); #endif } #ifdef USE_STORE_LOG_STR_IN_FLASH -void HOT esp_log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format, - va_list args) { // NOLINT +// Remove before 2026.9.0 +void HOT esp_log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format, va_list args) { #ifdef USE_LOGGER - auto *log = logger::global_logger; - if (log == nullptr) - return; - - log->log_vprintf_(static_cast(level), tag, line, format, args); + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); + logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, args); #endif } #endif @@ -49,11 +73,13 @@ void HOT esp_log_vprintf_(int level, const char *tag, int line, const __FlashStr #ifdef USE_ESP32 int HOT esp_idf_log_vprintf_(const char *format, va_list args) { // NOLINT #ifdef USE_LOGGER - auto *log = logger::global_logger; - if (log == nullptr) +#ifdef ESPHOME_DEBUG + if (logger::global_logger == nullptr) { + early_log_printf_("esp-idf", 0, format, args); return 0; - - log->log_vprintf_(ESPHOME_LOG_LEVEL, "esp-idf", 0, format, args); + } +#endif + logger::global_logger->log_vprintf_(ESPHOME_LOG_LEVEL, "esp-idf", 0, format, args); #endif return 0; } diff --git a/esphome/core/log.h b/esphome/core/log.h index a2c4b35c6e..ff39633142 100644 --- a/esphome/core/log.h +++ b/esphome/core/log.h @@ -4,6 +4,14 @@ #include #include + +// Debug assert that only fires when ESPHOME_DEBUG is defined (e.g. in CI/test builds). +// Zero cost in production firmware. +#ifdef ESPHOME_DEBUG +#define ESPHOME_DEBUG_ASSERT(expr) assert(expr) // NOLINT +#else +#define ESPHOME_DEBUG_ASSERT(expr) ((void) 0) +#endif // for PRIu32 and friends #include #include @@ -61,7 +69,9 @@ void esp_log_printf_(int level, const char *tag, int line, const __FlashStringHe #endif void esp_log_vprintf_(int level, const char *tag, int line, const char *format, va_list args); // NOLINT #ifdef USE_STORE_LOG_STR_IN_FLASH -void esp_log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format, va_list args); +// Remove before 2026.9.0 +__attribute__((deprecated("Use esp_log_printf_() instead. Removed in 2026.9.0."))) void esp_log_vprintf_( + int level, const char *tag, int line, const __FlashStringHelper *format, va_list args); #endif #if defined(USE_ESP32) int esp_idf_log_vprintf_(const char *format, va_list args); // NOLINT diff --git a/script/cpp_unit_test.py b/script/cpp_unit_test.py index e11687dc16..c917458472 100755 --- a/script/cpp_unit_test.py +++ b/script/cpp_unit_test.py @@ -78,6 +78,7 @@ def create_test_config(config_name: str, includes: list[str]) -> dict: "build_flags": [ "-Og", # optimize for debug "-DUSE_TIME_TIMEZONE", # enable timezone code paths for testing + "-DESPHOME_DEBUG", # enable debug assertions ], "debug_build_flags": [ # only for debug builds "-g3", # max debug info diff --git a/tests/component_tests/logger/__init__.py b/tests/component_tests/logger/__init__.py new file mode 100644 index 0000000000..e69de29bb2 diff --git a/tests/component_tests/logger/test_logger.py b/tests/component_tests/logger/test_logger.py new file mode 100644 index 0000000000..98aa741964 --- /dev/null +++ b/tests/component_tests/logger/test_logger.py @@ -0,0 +1,50 @@ +"""Tests for the logger component.""" + +import re + + +def test_logger_pre_setup_before_other_components(generate_main): + """Logger::pre_setup() must be called before any other component is created. + + Log functions call global_logger->log_vprintf_() without a null check, + so global_logger must be set before anything can log. + """ + main_cpp = generate_main("tests/component_tests/logger/test_logger.yaml") + + # Find the logger's pre_setup() call specifically + logger_pre_setup = re.search(r"logger_logger->pre_setup\(\)", main_cpp) + if logger_pre_setup is None: + # Fall back to finding any logger-related pre_setup + logger_pre_setup = re.search(r"logger\w*->pre_setup\(\)", main_cpp) + assert logger_pre_setup is not None, ( + "Logger pre_setup() not found in generated code" + ) + + # Find all "new " allocations (component creation) + new_allocations = list(re.finditer(r"\bnew [\w:]+", main_cpp)) + assert len(new_allocations) > 0, "No component allocations found" + + # Separate logger and non-logger allocations + logger_allocs = [a for a in new_allocations if "logger" in a.group().lower()] + non_logger_allocs = [ + a + for a in new_allocations + if "logger" not in a.group().lower() + # Skip placement new for App + and "(&App)" not in main_cpp[max(0, a.start() - 5) : a.start()] + ] + + assert len(logger_allocs) > 0, ( + f"Logger allocation not found in: {[a.group() for a in new_allocations]}" + ) + assert len(non_logger_allocs) > 0, ( + "No non-logger component allocations found — " + "add a component to test_logger.yaml so the ordering check is meaningful" + ) + + # All non-logger allocations must appear after logger pre_setup() + for alloc in non_logger_allocs: + assert alloc.start() > logger_pre_setup.start(), ( + f"Component allocation '{alloc.group()}' at position {alloc.start()} " + f"appears before logger pre_setup() at position {logger_pre_setup.start()}" + ) diff --git a/tests/component_tests/logger/test_logger.yaml b/tests/component_tests/logger/test_logger.yaml new file mode 100644 index 0000000000..f43e99d94f --- /dev/null +++ b/tests/component_tests/logger/test_logger.yaml @@ -0,0 +1,14 @@ +--- +esphome: + name: test + +esp8266: + board: d1_mini_lite + +logger: + level: DEBUG + +# Need at least one non-logger component so the ordering test +# can verify that logger pre_setup() comes before other allocations. +preferences: + flash_write_interval: 1min diff --git a/tests/components/main.cpp b/tests/components/main.cpp index 928f0e6059..373fde7151 100644 --- a/tests/components/main.cpp +++ b/tests/components/main.cpp @@ -1,5 +1,7 @@ #include +#include "esphome/components/logger/logger.h" + /* This special main.cpp replaces the default one. It will run all the Google Tests found in all compiled cpp files and then exit with the result @@ -18,6 +20,12 @@ void original_setup() { } void setup() { + // Log functions call global_logger->log_vprintf_() without a null check, + // so we must set up a Logger before any test that triggers logging. + static esphome::logger::Logger test_logger(0); + test_logger.set_log_level(ESPHOME_LOG_LEVEL); + test_logger.pre_setup(); + ::testing::InitGoogleTest(); int exit_code = RUN_ALL_TESTS(); exit(exit_code); diff --git a/tests/integration/conftest.py b/tests/integration/conftest.py index b7f7fc60b3..b652b4174c 100644 --- a/tests/integration/conftest.py +++ b/tests/integration/conftest.py @@ -193,6 +193,7 @@ async def yaml_config(request: pytest.FixtureRequest, unused_tcp_port: int) -> s " platformio_options:\n" " build_flags:\n" ' - "-DDEBUG" # Enable assert() statements\n' + ' - "-DESPHOME_DEBUG" # Enable ESPHOME_DEBUG_ASSERT checks\n' ' - "-DESPHOME_DEBUG_API" # Enable API protocol asserts\n' ' - "-g" # Add debug symbols', )