From 8a2514a9c94e5c717e3c07d72b27b7f04b67648c Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Mar 2026 21:47:25 -1000 Subject: [PATCH 1/6] [log] Remove null check indirection from log functions Call global_logger->log_vprintf_() directly without null-checking global_logger on every log call. Logger::pre_setup() sets global_logger before any other component is created in the generated setup() function, so it is guaranteed to be valid by the time any log function is invoked. Also removes the __FlashStringHelper* esp_log_vprintf_ overload which was dead code (only called from esp_log_printf_, never directly). Add a Python codegen test to verify the ordering invariant, and a comment on App.pre_setup() documenting the constraint. --- esphome/core/application.h | 1 + esphome/core/log.cpp | 31 ++++--------- tests/component_tests/logger/__init__.py | 0 tests/component_tests/logger/test_logger.py | 43 +++++++++++++++++++ tests/component_tests/logger/test_logger.yaml | 9 ++++ 5 files changed, 61 insertions(+), 23 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/core/application.h b/esphome/core/application.h index 40f8a00edd3..11e5f07c080 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -138,6 +138,7 @@ static constexpr uint32_t TEARDOWN_TIMEOUT_REBOOT_MS = 1000; // 1 second for qu class Application { public: + // Called before Logger::pre_setup() — must not log (global_logger is not yet set). void pre_setup(const std::string &name, const std::string &friendly_name, bool name_add_mac_suffix) { arch_init(); this->name_add_mac_suffix_ = name_add_mac_suffix; diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index 8bf188ddbbd..ad641f19814 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -8,52 +8,37 @@ namespace esphome { -// Call log_vprintf_ directly to avoid extra indirection through esp_log_vprintf_ +// No null check on global_logger — Logger::pre_setup() sets global_logger +// before any other component is created in the generated setup() function, +// so it is guaranteed to be valid by the time any log function is invoked. void HOT esp_log_printf_(int level, const char *tag, int line, const char *format, ...) { // NOLINT #ifdef USE_LOGGER - auto *log = logger::global_logger; - if (log == nullptr) - return; - va_list arg; va_start(arg, format); - log->log_vprintf_(static_cast(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 - auto *log = logger::global_logger; - if (log == nullptr) - return; - va_list arg; va_start(arg, format); - log->log_vprintf_(static_cast(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) - return; - - log->log_vprintf_(static_cast(level), tag, line, format, args); + logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, args); #endif } #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) - return 0; - - log->log_vprintf_(ESPHOME_LOG_LEVEL, "esp-idf", 0, format, args); + logger::global_logger->log_vprintf_(ESPHOME_LOG_LEVEL, "esp-idf", 0, format, args); #endif return 0; } diff --git a/tests/component_tests/logger/__init__.py b/tests/component_tests/logger/__init__.py new file mode 100644 index 00000000000..e69de29bb2d diff --git a/tests/component_tests/logger/test_logger.py b/tests/component_tests/logger/test_logger.py new file mode 100644 index 00000000000..83f8caa2d82 --- /dev/null +++ b/tests/component_tests/logger/test_logger.py @@ -0,0 +1,43 @@ +"""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 position of logger pre_setup + pre_setup_match = re.search(r"->pre_setup\(\)", main_cpp) + assert pre_setup_match 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" + + # Find the logger allocation + logger_new = None + for alloc in new_allocations: + if "logger" in alloc.group(): + logger_new = alloc + break + + assert logger_new is not None, ( + f"Logger allocation not found in: {[a.group() for a in new_allocations]}" + ) + + # All non-logger allocations must appear after pre_setup() + for alloc in new_allocations: + if alloc == logger_new: + continue + # Skip "new (&App)" placement new which is before logger + if "(&App)" in main_cpp[max(0, alloc.start() - 5) : alloc.start()]: + continue + assert alloc.start() > pre_setup_match.start(), ( + f"Component allocation '{alloc.group()}' at position {alloc.start()} " + f"appears before logger pre_setup() at position {pre_setup_match.start()}" + ) diff --git a/tests/component_tests/logger/test_logger.yaml b/tests/component_tests/logger/test_logger.yaml new file mode 100644 index 00000000000..5d983cb3f5d --- /dev/null +++ b/tests/component_tests/logger/test_logger.yaml @@ -0,0 +1,9 @@ +--- +esphome: + name: test + +esp8266: + board: d1_mini_lite + +logger: + level: DEBUG From 8d36935083582a3e41db4e93d387935d1665034a Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Mar 2026 21:49:26 -1000 Subject: [PATCH 2/6] [log] Strengthen comment about no null checks on hot path --- esphome/core/log.cpp | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index ad641f19814..13a1fef5f71 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -8,9 +8,13 @@ namespace esphome { -// No null check on global_logger — Logger::pre_setup() sets global_logger -// before any other component is created in the generated setup() function, -// so it is guaranteed to be valid by the time any log function is invoked. +// IMPORTANT: Do not add null checks on global_logger here. +// These functions are the hot path for ALL logging across the entire firmware, +// so every instruction matters. Logger::pre_setup() sets global_logger before +// any other component is created in the generated setup() function, so it is +// guaranteed to be valid by the time any log function is invoked. This invariant +// is enforced by codegen ordering and tested in +// tests/component_tests/logger/test_logger.py. void HOT esp_log_printf_(int level, const char *tag, int line, const char *format, ...) { // NOLINT #ifdef USE_LOGGER va_list arg; From 92a37d4cb09fe8ef2c64c47cc441ba8be471452d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Mar 2026 22:00:06 -1000 Subject: [PATCH 3/6] [log] Initialize Logger in C++ test framework Log functions call global_logger->log_vprintf_() without a null check. The test main.cpp skips the generated setup() (which calls Logger::pre_setup()), so set up a static Logger before running tests. --- tests/components/main.cpp | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/tests/components/main.cpp b/tests/components/main.cpp index 928f0e60593..373fde71516 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); From d8600b5bc9bc603ac2ad4bb2d18defe2da3c118a Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Mar 2026 22:02:13 -1000 Subject: [PATCH 4/6] [log] Add missing USE_LOGGER guard on FlashStringHelper overload --- esphome/core/log.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index 13a1fef5f71..c103bf331e0 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -26,10 +26,12 @@ void HOT esp_log_printf_(int level, const char *tag, int line, const char *forma #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 va_list arg; va_start(arg, format); logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, arg); va_end(arg); +#endif } #endif From 6e36af6c4b8d6fa46adce6fc034888c88fcca4bf Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Mar 2026 22:05:17 -1000 Subject: [PATCH 5/6] [log] Add ESPHOME_DEBUG_ASSERT for log function invariants Add ESPHOME_DEBUG_ASSERT macro that only fires when ESPHOME_DEBUG is defined. Use it to assert global_logger is not null in log functions. Enable ESPHOME_DEBUG in C++ unit test builds so these assertions are active during testing but have zero cost in production firmware. --- esphome/core/log.cpp | 4 ++++ esphome/core/log.h | 8 ++++++++ script/cpp_unit_test.py | 1 + 3 files changed, 13 insertions(+) diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index c103bf331e0..f92b59fe134 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -17,6 +17,7 @@ namespace esphome { // tests/component_tests/logger/test_logger.py. void HOT esp_log_printf_(int level, const char *tag, int line, const char *format, ...) { // NOLINT #ifdef USE_LOGGER + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); va_list arg; va_start(arg, format); logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, arg); @@ -27,6 +28,7 @@ void HOT esp_log_printf_(int level, const char *tag, int line, const char *forma #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); logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, arg); @@ -37,6 +39,7 @@ void HOT esp_log_printf_(int level, const char *tag, int line, const __FlashStri void HOT esp_log_vprintf_(int level, const char *tag, int line, const char *format, va_list args) { // NOLINT #ifdef USE_LOGGER + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); logger::global_logger->log_vprintf_(static_cast(level), tag, line, format, args); #endif } @@ -44,6 +47,7 @@ void HOT esp_log_vprintf_(int level, const char *tag, int line, const char *form #ifdef USE_ESP32 int HOT esp_idf_log_vprintf_(const char *format, va_list args) { // NOLINT #ifdef USE_LOGGER + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); 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 14a0cb0572a..134e8161504 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 diff --git a/script/cpp_unit_test.py b/script/cpp_unit_test.py index b87261ab332..6ba4127848b 100755 --- a/script/cpp_unit_test.py +++ b/script/cpp_unit_test.py @@ -100,6 +100,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 From 1fa99305f9f1a586fb4c0efcf510192c140ebf3c Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Mar 2026 22:05:36 -1000 Subject: [PATCH 6/6] [log] Enable ESPHOME_DEBUG in integration tests --- tests/integration/conftest.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/integration/conftest.py b/tests/integration/conftest.py index b7f7fc60b3b..b652b4174cc 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', )