diff --git a/esphome/core/application.h b/esphome/core/application.h index 577d9d8ebed..ef18566182b 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -145,6 +145,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(); @@ -169,6 +170,7 @@ class Application { #endif } #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 8bf188ddbbd..f92b59fe134 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -8,29 +8,30 @@ namespace esphome { -// Call log_vprintf_ directly to avoid extra indirection through esp_log_vprintf_ +// 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 - auto *log = logger::global_logger; - if (log == nullptr) - return; - + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); 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; - + ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr); 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 } @@ -38,22 +39,16 @@ 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 - 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 } #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); + 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 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 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); 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', )