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