From 7235c2a8d62d1bc365513c64dd11268a4c02715b Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 26 Aug 2026 21:44:28 -0500 Subject: [PATCH] [logger] Move the Log V2 wrap into the logger component The Log V2 enable block and the esp_log_format wrap belong to the logger: the wrap routes IDF output through the logger's hook, and the logger already owns the esp8266 ets_putc wrap and esp32 console sdkconfig options. This also drops the CORE.config peek at the logger key from the esp32 platform. The direct formatter now reuses LogBuffer and the logger's level tables instead of hand rolled equivalents, uses a smaller stack buffer, and the hot path tests the common case first. --- esphome/components/esp32/__init__.py | 20 ---- esphome/components/logger/__init__.py | 11 +++ esphome/components/logger/logger_esp32.cpp | 60 +++++++++++ esphome/core/log.cpp | 110 --------------------- 4 files changed, 71 insertions(+), 130 deletions(-) diff --git a/esphome/components/esp32/__init__.py b/esphome/components/esp32/__init__.py index 4980d30ee4..9ce50bb07c 100644 --- a/esphome/components/esp32/__init__.py +++ b/esphome/components/esp32/__init__.py @@ -26,7 +26,6 @@ from esphome.const import ( CONF_IGNORE_EFUSE_CUSTOM_MAC, CONF_IGNORE_EFUSE_MAC_CRC, CONF_LOG_LEVEL, - CONF_LOGGER, CONF_NAME, CONF_OTA, CONF_PATH, @@ -2692,25 +2691,6 @@ async def to_code(config): # This saves ~250 bytes of RAM (tag cache) and associated code add_idf_sdkconfig_option("CONFIG_LOG_TAG_LEVEL_IMPL_NONE", True) - # ESP-IDF Log V2 centralizes formatting inside esp_log(), removing the - # per-site macro expansions of V1 (saves ~4KB flash, ~180B RAM). Only enable - # on IDF >= 6.1, where CONFIG_LOG_API_CONSTRAINED_ENV_SAFE=n lets - # ESP_DRAM_LOGx / ESP_EARLY_LOGx expand directly to esp_rom_printf and drops - # the ~1.2KB esp_rom_vprintf that would otherwise sit in IRAM. Below 6.1 the - # option does not exist, so we stay on V1 unchanged. Also requires the - # logger component: the esp_log_format override in core/log.cpp integrates - # V2 with ESPHome's logger hook, and without the logger there is no hook to - # integrate with, so such builds stay on V1 as well. - if idf_version() >= cv.Version(6, 1, 0) and CONF_LOGGER in CORE.config: - add_idf_sdkconfig_option("CONFIG_LOG_VERSION_1", False) - add_idf_sdkconfig_option("CONFIG_LOG_VERSION_2", True) - add_idf_sdkconfig_option("CONFIG_LOG_API_CONSTRAINED_ENV_SAFE", False) - cg.add_define("USE_ESP32_LOG_V2") - # Intercept liblog's formatter via --wrap; a plain strong definition - # collides instead of overriding because liblog resolves the symbol - # within its own archive (see core/log.cpp). - cg.add_build_flag("-Wl,--wrap=esp_log_format") - # Reduce PHY TX power in the event of a brownout add_idf_sdkconfig_option("CONFIG_ESP_PHY_REDUCE_TX_POWER", True) diff --git a/esphome/components/logger/__init__.py b/esphome/components/logger/__init__.py index 07b8b03084..9eff58c8a8 100644 --- a/esphome/components/logger/__init__.py +++ b/esphome/components/logger/__init__.py @@ -20,6 +20,7 @@ from esphome.components.esp32 import ( VARIANT_ESP32S31, add_idf_sdkconfig_option, get_esp32_variant, + idf_version, require_usb_serial_jtag_secondary, require_vfs_termios, ) @@ -459,6 +460,16 @@ async def _late_logger_init(config: ConfigType) -> None: elif config[CONF_HARDWARE_UART] == USB_SERIAL_JTAG: add_idf_sdkconfig_option("CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG", True) cg.add_define("USE_LOGGER_UART_SELECTION_USB_SERIAL_JTAG") + # Log V2 formats centrally in esp_log() (~4KB flash, ~180B RAM). 6.1 + # adds CONSTRAINED_ENV_SAFE=n, keeping early/DRAM logs on + # esp_rom_printf instead of pulling ~1.2KB esp_rom_vprintf into IRAM. + if idf_version() >= cv.Version(6, 1, 0): + add_idf_sdkconfig_option("CONFIG_LOG_VERSION_1", False) + add_idf_sdkconfig_option("CONFIG_LOG_VERSION_2", True) + add_idf_sdkconfig_option("CONFIG_LOG_API_CONSTRAINED_ENV_SAFE", False) + cg.add_define("USE_ESP32_LOG_V2") + # --wrap: a strong definition collides; see logger_esp32.cpp + cg.add_build_flag("-Wl,--wrap=esp_log_format") # Define platform support flags for components that need auto-detection try: uart_selection(USB_SERIAL_JTAG) diff --git a/esphome/components/logger/logger_esp32.cpp b/esphome/components/logger/logger_esp32.cpp index 05fc959ceb..4148ec46a9 100644 --- a/esphome/components/logger/logger_esp32.cpp +++ b/esphome/components/logger/logger_esp32.cpp @@ -149,4 +149,64 @@ const LogString *Logger::get_uart_selection_() { } } // namespace esphome::logger + +#ifdef USE_ESP32_LOG_V2 +#include +#include +#include + +namespace esphome::logger { + +// IDF levels NONE=0 E=1 W=2 I=3 D=4 V=5; ESPHome inserts CONFIG at 4 +static inline uint8_t idf_to_esphome_level(uint8_t idf_level) { + if (idf_level <= 3) + return idf_level; + return idf_level >= 5 ? ESPHOME_LOG_LEVEL_VERBOSE : ESPHOME_LOG_LEVEL_DEBUG; +} + +// Console output without the logger hook: early boot and constrained env +// (fwrite locks crash during PHY init on USB JTAG). Cold path. +static void __attribute__((noinline)) esp_log_format_direct(esp_log_msg_t *message) { + // Constrained-env stacks are small; enough for IDF's own one-liners + char stack_buf[256]; + LogBuffer buf{stack_buf, sizeof(stack_buf)}; + buf.write_header(idf_to_esphome_level(message->config.opts.log_level), message->tag ? message->tag : "esp-idf", 0, + nullptr); + buf.format_body(message->format, message->args); + esp_rom_printf("%s\n", stack_buf); +} + +} // namespace esphome::logger + +extern "C" { +// Replaces liblog's formatter, which calls the vprintf hook 3x per message +// (header, body, newline). --wrap because a strong definition collides: +// liblog resolves the symbol within its own archive. Not IRAM_ATTR: cache-off +// callers bypass esp_log() under CONSTRAINED_ENV_SAFE=n. +void __wrap_esp_log_format(esp_log_msg_t *message) { // NOLINT + extern vprintf_like_t esp_log_vprint_func; + if (esp_log_vprint_func == &esphome::esp_idf_log_vprintf_) [[likely]] { + if (message->config.opts.constrained_env) [[unlikely]] { + esphome::logger::esp_log_format_direct(message); + return; + } + // Call the logger directly with V2's separate tag and severity so lines + // render as e.g. "[E][wifi]:"; the hook signature cannot carry them. + // global_logger is set before the hook is installed (pre_setup above). + esphome::logger::global_logger->log_vprintf_(esphome::logger::idf_to_esphome_level(message->config.opts.log_level), + message->tag ? message->tag : "esp-idf", 0, message->format, + message->args); + return; + } + extern int vprintf(const char *, __gnuc_va_list); // NOLINT + if (esp_log_vprint_func == &vprintf || message->config.opts.constrained_env) { + // No hook yet (early boot) or constrained env: direct console output + esphome::logger::esp_log_format_direct(message); + return; + } + // Custom hook via esp_log_set_vprintf: forward the body as-is + esp_log_vprint_func(message->format, message->args); +} +} // extern "C" +#endif // USE_ESP32_LOG_V2 #endif diff --git a/esphome/core/log.cpp b/esphome/core/log.cpp index 346c68eaa3..9fcddfeff6 100644 --- a/esphome/core/log.cpp +++ b/esphome/core/log.cpp @@ -76,113 +76,3 @@ int HOT esp_idf_log_vprintf_(const char *format, va_list args) { // NOLINT #endif } // namespace esphome - -// Only compiled when the logger component is present: the override exists to -// integrate V2 with ESPHome's logger hook. Without the logger no hook is ever -// installed, so liblog's stock esp_log_format links in and console output -// stays bone-stock ESP-IDF (V2's flash savings still apply). -#if defined(USE_ESP32_LOG_V2) && defined(USE_LOGGER) && !defined(BOOTLOADER_BUILD) -// Override esp_log_format to prevent V2's 3-call vprintf fragmentation. -// Without this, Log V2 calls the vprintf hook 3 times per message (header, -// body, newline) which creates 3 separate log entries in ESPHome's logger. -// Interception uses the linker's --wrap (added in esp32/__init__.py when Log -// V2 is enabled): a plain strong definition cannot win here because liblog's -// log.c.obj references esp_log_format and the linker resolves it from -// log_format_text.c.obj within the same archive, before ever reaching -// ESPHome's archive, which then collides as a duplicate definition. -#include -#include - -// Format an ESP-IDF log message directly to the console, bypassing the -// ESPHome logger hook. Used when the hook isn't installed (early boot) or -// can't be used safely (constrained env: PHY init, efuse reads -- fwrite -// locks crash on USB JTAG devices). -// Formats in ESPHome style with ANSI colors into a 512-byte stack buffer, -// then outputs atomically via esp_rom_printf. -// This path is cold on 99.9% of builds -- it only runs during early boot -// and at DEBUG framework log level (default is ERROR). -static void __attribute__((noinline)) esp_log_format_direct_(esp_log_msg_t *message) { // NOLINT - // ESP-IDF levels: NONE=0 ERROR=1 WARN=2 INFO=3 DEBUG=4 VERBOSE=5 - // Color digits: E=1(red) W=3(yellow) I=2(green) D=6(cyan) V=7(gray) - static const char COLOR_DIGIT[] = {'\0', '1', '3', '2', '6', '7'}; - static const char LVL[] = {'\0', 'E', 'W', 'I', 'D', 'V'}; - // Format into stack buffer and output atomically via esp_rom_printf. - // Can't use fwrite (locks crash during early boot and PHY init). - char buf[512]; - int pos = 0; - uint8_t level = message->config.opts.log_level; - if (level > 0 && level < sizeof(LVL)) { - pos = snprintf(buf, sizeof(buf), "\033[0;3%cm[%c][%s]: ", COLOR_DIGIT[level], LVL[level], - message->tag ? message->tag : "idf"); - // Clamp: snprintf returns the untruncated length (or negative on error), - // so an oversized tag or an encoding error would otherwise leave pos - // outside the buffer and break every bound check below. - if (pos < 0) { - pos = 0; - } else if (pos >= (int) sizeof(buf)) { - pos = sizeof(buf) - 1; - } - } - if (pos < (int) sizeof(buf) - 2) { - int body = vsnprintf(buf + pos, sizeof(buf) - pos, message->format, message->args); - if (body > 0) - pos += (body < (int) sizeof(buf) - pos) ? body : (int) sizeof(buf) - pos - 1; - } - if (level > 0 && level < sizeof(LVL) && pos < (int) sizeof(buf) - 6) { - pos += snprintf(buf + pos, sizeof(buf) - pos, "\033[0m"); - } - if (pos < (int) sizeof(buf) - 1) { - buf[pos++] = '\n'; - } - buf[pos] = '\0'; - esp_rom_printf("%s", buf); -} - -extern "C" { -// Wrap of esp_log_format from liblog.a (via -Wl,--wrap=esp_log_format) to -// prevent V2's 3-call vprintf fragmentation. Deliberately NOT IRAM_ATTR: every -// caller that must work with flash cache disabled (ESP_DRAM_LOGx, -// ESP_EARLY_LOGx) bypasses esp_log() entirely under -// CONFIG_LOG_API_CONSTRAINED_ENV_SAFE=n, and both paths below immediately call -// flash-resident code anyway, so IRAM placement would only spend the IRAM this -// change exists to save. -void __wrap_esp_log_format(esp_log_msg_t *message) { // NOLINT - extern vprintf_like_t esp_log_vprint_func; - extern int vprintf(const char *, __gnuc_va_list); // NOLINT - if (esp_log_vprint_func == &vprintf || message->config.opts.constrained_env) [[unlikely]] { - // Early boot or constrained env (PHY init, efuse reads, scheduler not - // running). Can't use the ESPHome hook -- fwrite locks crash during PHY - // init on USB JTAG devices and newlib isn't initialized during early boot. - // Format to stack buffer with vsnprintf + esp_rom_printf instead. - // - // Note: if called from an ISR with flash cache disabled, this will crash - // because the format string and tag are in flash. This is the same as V1 - // where ESP_EARLY_LOGx from ISR also used flash-resident format strings - // via esp_rom_printf. No ESP-IDF code is known to log from ISR with - // cache disabled. - esp_log_format_direct_(message); - return; - } - // After hook installed, normal environment. Never call the esp_log_vprintf - // inline here: it would pull in esp_rom_vprintf (1.2KB IRAM). - if (esp_log_vprint_func == &esphome::esp_idf_log_vprintf_ && esphome::logger::global_logger != nullptr) { - // The hook is ESPHome's own (the common case). V2 keeps the component tag - // (wifi, phy_init, ...) and per-message severity separate from the format - // string, so call the logger directly with both: lines render with the - // real tag and level (e.g. "[E][wifi]: ...") including color and per-tag - // filtering, details the (format, args) hook signature cannot carry. - // IDF levels: NONE=0 E=1 W=2 I=3 D=4 V=5; ESPHome inserts CONFIG at 4. - static const uint8_t LEVEL_MAP[] = {ESPHOME_LOG_LEVEL_NONE, ESPHOME_LOG_LEVEL_ERROR, ESPHOME_LOG_LEVEL_WARN, - ESPHOME_LOG_LEVEL_INFO, ESPHOME_LOG_LEVEL_DEBUG, ESPHOME_LOG_LEVEL_VERBOSE}; - uint8_t idf_level = message->config.opts.log_level; - uint8_t level = idf_level < sizeof(LEVEL_MAP) ? LEVEL_MAP[idf_level] : ESPHOME_LOG_LEVEL_VERBOSE; - esphome::logger::global_logger->log_vprintf_(level, message->tag ? message->tag : "esp-idf", 0, message->format, - message->args); - return; - } - // A custom hook was installed via esp_log_set_vprintf: honor it and forward - // the message body as-is. - esp_log_vprint_func(message->format, message->args); -} -} // extern "C" -#endif