Merge origin/log-skip-vprintf-indirection into integration

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();

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<uint8_t>(level), tag, line, format, arg);
+  logger::global_logger->log_vprintf_(static_cast<uint8_t>(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<uint8_t>(level), tag, line, format, arg);
+  logger::global_logger->log_vprintf_(static_cast<uint8_t>(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<uint8_t>(level), tag, line, format, args);
+  ESPHOME_DEBUG_ASSERT(logger::global_logger != nullptr);
+  logger::global_logger->log_vprintf_(static_cast<uint8_t>(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;
 }

esphome/core/log.h

@@ -4,6 +4,14 @@
 
 #include <cassert>
 #include <cstdarg>
+
+// 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 <cinttypes>
 #include <string>

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

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()}"
+        )

tests/component_tests/logger/test_logger.yaml

@@ -0,0 +1,9 @@
+---
+esphome:
+  name: test
+
+esp8266:
+  board: d1_mini_lite
+
+logger:
+  level: DEBUG

tests/components/main.cpp

@@ -1,5 +1,7 @@
 #include <gtest/gtest.h>
 
+#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);

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',
         )