Compare commits

...

8 Commits

Author SHA1 Message Date
J. Nick Koston
fd3aa3f2ef [esp32] IRAM_ATTR on dispatch, document cold path
Put IRAM_ATTR back on esp_log_format (tiny ~43 byte dispatch function)
to match esp_log_va's IRAM placement and avoid cache miss. Leave the
512-byte formatting function in flash — it's cold on 99.9% of builds
(only runs during early boot and at DEBUG framework log level).
2026-03-13 18:18:19 -10:00
J. Nick Koston
4fbd0f1595 [esp32] Rename esp_log_format_early_ to esp_log_format_direct_ 2026-03-13 18:10:30 -10:00
J. Nick Koston
dc2d241c49 [esp32] Remove IRAM_ATTR from esp_log_format override 2026-03-13 18:09:03 -10:00
J. Nick Koston
5adc673981 [esp32] Remove pointless ISR check, document flash limitation
The ISR with cache disabled case can't be handled without
esp_rom_vprintf — the caller's format string and tag are also in
flash, so even esp_rom_printf would crash. This is the same
limitation V1 had. Document it and keep the simpler code.
2026-03-13 18:07:49 -10:00
J. Nick Koston
623f7249b8 [esp32] Add ISR safety check for constrained env logging
constrained_env combines three conditions: scheduler not running,
in ISR, or cache disabled. Only the first is safe for flash access.

Check xPortInIsrContext() (IRAM-resident) explicitly:
- In ISR: output tag only via esp_rom_printf (ROM). Flash may be
  inaccessible. This matches V1 behavior where ISR logging was
  best-effort.
- Not in ISR (scheduler not running, PHY init): call flash-resident
  esp_log_format_early_ which formats the full message.

This ensures the override is safe for all constrained env cases
without pulling in esp_rom_vprintf (1.2KB IRAM).
2026-03-13 18:05:07 -10:00
J. Nick Koston
98f0e53053 [esp32] Update stale comments and remove unused includes 2026-03-13 18:01:16 -10:00
J. Nick Koston
159005e91a [esp32] Use 512-byte stack buffer for early/constrained log formatting 2026-03-13 17:59:35 -10:00
J. Nick Koston
fac141e3fd [esp32] Avoid esp_rom_vprintf and fix constrained env crash
- Route constrained env (PHY init, efuse reads) through the early
  boot path which uses vsnprintf + esp_rom_printf. This avoids both
  the fwrite lock crash on USB JTAG devices and pulling in
  esp_rom_vprintf (1.2KB IRAM).
- Call esp_log_vprint_func directly on the normal path instead of
  going through the esp_log_vprintf inline (which would reference
  esp_rom_vprintf for the constrained env dispatch).
- Remove IRAM_ATTR from esp_log_format_early_ since it's only called
  when flash is accessible (early boot and constrained env with cache
  enabled like PHY init and efuse reads).
2026-03-13 17:58:42 -10:00

View File

@@ -88,78 +88,77 @@ int HOT esp_idf_log_vprintf_(const char *format, va_list args) { // NOLINT
} // namespace esphome
#if defined(USE_ESP32) && !defined(BOOTLOADER_BUILD)
// Override esp_log_format to disable ESP-IDF's own log formatting so that
// the vprintf hook receives a single call per message (just the user's format
// string + args). Without this, Log V2 makes 3 vprintf calls per message
// (header, body, newline) which fragments the output in ESPHome's logger.
// This strong definition overrides the archive symbol from ESP-IDF's liblog.
// It affects all callers including precompiled blobs (e.g. wifi).
//
// Before the ESPHome logger hook is installed (early boot), we fall through
// to the original ESP-IDF formatting so boot messages have proper formatting.
// 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.
// This strong definition overrides the archive symbol from ESP-IDF's liblog,
// affecting all callers including precompiled blobs (e.g. wifi).
#include <esp_private/log_message.h>
#include <esp_private/log_print.h>
#include <esp_private/log_format.h>
#include <esp_log_write.h>
// Outlined cold path for early boot / constrained environment logging.
// Uses esp_log_printf/esp_log_vprintf which dispatch to esp_rom_vprintf
// for constrained environments (same as ESP-IDF's original esp_log_format).
// Must be in IRAM since it's called from the IRAM esp_log_format during
// early boot when the scheduler isn't running (constrained_env=1).
static void IRAM_ATTR __attribute__((noinline)) esp_log_format_early_(esp_log_msg_t *message) {
// 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) {
// 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)
// DRAM_ATTR required: this function is IRAM_ATTR and may be called from constrained
// environments where flash cache is disabled. All string constants must be in DRAM.
// ESP-IDF's own log_format_text.c achieves this via linker fragment (noflash), but
// our override is in a different compilation unit so we must use DRAM_ATTR explicitly.
static DRAM_ATTR const char color_digit[] = {'\0', '1', '3', '2', '6', '7'};
static DRAM_ATTR const char lvl[] = {'\0', 'E', 'W', 'I', 'D', 'V'};
static DRAM_ATTR const char fmt_header[] = "\033[0;3%cm[%c][%s]: ";
static DRAM_ATTR const char fmt_reset_nl[] = "\033[0m\n";
static DRAM_ATTR const char fmt_nl[] = "\n";
static DRAM_ATTR const char tag_fallback[] = "idf";
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 CONFIG_LIBC_NEWLIB
if (!message->config.opts.constrained_env) {
flockfile(stdout);
}
#endif
if (level > 0 && level < sizeof(lvl)) {
esp_log_printf(message->config, fmt_header, color_digit[level], lvl[level],
message->tag ? message->tag : tag_fallback);
pos = snprintf(buf, sizeof(buf), "\033[0;3%cm[%c][%s]: ", color_digit[level], lvl[level],
message->tag ? message->tag : "idf");
}
esp_log_vprintf(message->config, message->format, message->args);
if (level > 0 && level < sizeof(lvl)) {
esp_log_printf(message->config, fmt_reset_nl);
} else {
esp_log_printf(message->config, fmt_nl);
if (pos >= 0 && 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 CONFIG_LIBC_NEWLIB
if (!message->config.opts.constrained_env) {
funlockfile(stdout);
if (level > 0 && level < sizeof(lvl) && pos < (int) sizeof(buf) - 6) {
pos += snprintf(buf + pos, sizeof(buf) - pos, "\033[0m");
}
#endif
if (pos < (int) sizeof(buf) - 1) {
buf[pos++] = '\n';
}
buf[pos] = '\0';
esp_rom_printf("%s", buf);
}
extern "C" {
// IRAM_ATTR required because ESP-IDF places esp_log_format in IRAM when
// CONFIG_LOG_IN_IRAM is enabled, and it may be called from constrained
// environments (ISR, cache disabled) where flash is inaccessible.
// Override esp_log_format from liblog.a to prevent V2's 3-call vprintf
// fragmentation. IRAM_ATTR to match esp_log_va's IRAM placement and avoid
// an IRAM→flash cache miss on every ESP-IDF log call. This function is
// tiny (~43 bytes) so the IRAM cost is negligible.
void IRAM_ATTR esp_log_format(esp_log_msg_t *message) {
// Check if ESPHome's vprintf hook is installed by comparing against default.
// Before logger init, esp_log_vprint_func == &vprintf (the default).
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 (ISR, cache disabled):
// use ROM functions only — flash may be inaccessible.
esp_log_format_early_(message);
// 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: skip formatting, forward body only
esp_log_vprintf(message->config, message->format, message->args);
// After hook installed, normal environment: skip formatting, forward body only.
// Call esp_log_vprint_func directly to avoid pulling in esp_rom_vprintf
// (1.2KB IRAM) through the esp_log_vprintf inline.
esp_log_vprint_func(message->format, message->args);
}
} // extern "C"
#endif