From 5b4ae22f581c8f1f83fa39ff2bcf1be0f8ded962 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 16 Jul 2026 02:08:28 -1000 Subject: [PATCH] [api] Don't spam tracebacks when decoding a crash without a local build (#17597) --- esphome/components/api/client.py | 25 ++++--- esphome/components/esp32/__init__.py | 16 ++-- esphome/espidf/toolchain.py | 8 ++ .../unit_tests/components/api/test_client.py | 36 +++++++-- tests/unit_tests/test_espidf_toolchain.py | 74 ++++++++++++++++++- 5 files changed, 135 insertions(+), 24 deletions(-) diff --git a/esphome/components/api/client.py b/esphome/components/api/client.py index 44edc035f9..98edfef038 100644 --- a/esphome/components/api/client.py +++ b/esphome/components/api/client.py @@ -18,7 +18,7 @@ with warnings.catch_warnings(): import contextlib from esphome.const import CONF_KEY, CONF_PORT, __version__ -from esphome.core import CORE, EsphomeError +from esphome.core import CORE from esphome.util import safe_print from . import CONF_ENCRYPTION @@ -36,15 +36,17 @@ class _LogLineProcessor: """Feeds incoming log lines to the stack-trace decoder. Two responsibilities beyond just calling the decoder: - 1. Catch EsphomeError. on_log runs inside an asyncio protocol - callback; if an exception escapes, the loop tears the transport - down with "Fatal error: protocol.data_received() call failed." - and ReconnectLogic immediately reconnects, the device replays - the same crash trace, and we loop forever. - 2. Disable decoding after the first failure. _decode_pc shells out - to PlatformIO via _run_idedata, which is expensive; a single - crash dump can contain many PC/BT lines and we don't want to - retry the failing subprocess for each one. + 1. Catch everything the decoder can raise. aioesphomeapi isolates + exceptions raised by log handlers, so an escaping one no longer + kills the session, but it does log a full traceback per line. A + crash dump carries a PC line plus one per backtrace frame, so the + tracebacks bury the dump the user is trying to read. Decoding is a + diagnostic nicety; nothing it raises is worth that noise. + 2. Disable decoding after the first failure. _decode_pc shells out to + the toolchain to resolve addr2line, which is expensive; a single + crash dump can contain many PC/BT lines and we don't want to retry + the failing subprocess for each one. This only works if every + failure is caught, which is why 1 is not narrowed to EsphomeError. """ def __init__(self, config: dict[str, Any], platform_handler: Any | None) -> None: @@ -61,12 +63,13 @@ class _LogLineProcessor: self.backtrace_state = self._platform_handler( self._config, raw_line, self.backtrace_state ) - except EsphomeError as exc: + except Exception as exc: # noqa: BLE001 # pylint: disable=broad-except self._decode_enabled = False self.backtrace_state = False # _run_idedata raises EsphomeError with no message; fall back # to a generic explanation when str(exc) is empty. detail = str(exc) or "build artifacts not found locally" + _LOGGER.debug("Stack-trace decoding failed", exc_info=True) _LOGGER.warning( "Crash trace decoding unavailable: %s. " "Run 'esphome compile' for this device to enable PC decoding.", diff --git a/esphome/components/esp32/__init__.py b/esphome/components/esp32/__init__.py index 9b568dd629..3c2fb35dde 100644 --- a/esphome/components/esp32/__init__.py +++ b/esphome/components/esp32/__init__.py @@ -3058,19 +3058,23 @@ def copy_files(): def _decode_pc(config, addr): - # _decode_pc runs from the api log processor's asyncio callback, which - # only catches EsphomeError. Any other exception escaping here tears down - # the protocol and triggers an infinite reconnect/replay loop. Convert - # toolchain-resolution errors (e.g. missing build dir / cmake cache) into - # EsphomeError so the caller can disable decoding cleanly. + # Convert toolchain-resolution errors (e.g. missing build dir / cmake + # cache) into EsphomeError. The api log processor stops decoding on any + # exception, so this is about the message it reports rather than about + # catching it at all: EsphomeError carries an explanation worth showing + # the user, where a raw OSError repr does not. if CORE.using_toolchain_esp_idf: from esphome.espidf import toolchain as idf_toolchain try: addr2line_path = idf_toolchain.get_addr2line_path() firmware_elf_path = idf_toolchain.get_elf_path() - except RuntimeError as err: + except (RuntimeError, OSError) as err: + # OSError covers a missing build directory or a cmake that isn't + # on PATH; both surface from the subprocess call, not as RuntimeError. raise EsphomeError(f"ESP-IDF toolchain not available: {err}") from err + if not firmware_elf_path.is_file(): + raise EsphomeError(f"Firmware ELF not found: {firmware_elf_path}") else: from esphome.platformio import toolchain diff --git a/esphome/espidf/toolchain.py b/esphome/espidf/toolchain.py index 231763d17d..f2bb99d970 100644 --- a/esphome/espidf/toolchain.py +++ b/esphome/espidf/toolchain.py @@ -94,6 +94,14 @@ def _get_idf_env(version: str | None = None) -> dict[str, str]: def _get_cmake_output(build_dir) -> str: cmake_output_cache = _cache().cmake_output if build_dir not in cmake_output_cache: + # Check the build before resolving the env: _get_idf_env() runs + # check_esp_idf_install(), which can download and install the whole + # framework. Never start that for a build that isn't there. Callers + # such as the log stack-trace decoder run against devices that were + # never compiled on this machine. + if not (Path(build_dir) / "CMakeCache.txt").is_file(): + raise EsphomeError(f"No ESP-IDF build found in {build_dir}") + cmd = ["cmake", "-LA", "-N", "."] env = _get_idf_env() diff --git a/tests/unit_tests/components/api/test_client.py b/tests/unit_tests/components/api/test_client.py index 333ef70b22..cbec406a3a 100644 --- a/tests/unit_tests/components/api/test_client.py +++ b/tests/unit_tests/components/api/test_client.py @@ -12,11 +12,9 @@ from esphome.core import EsphomeError def test_decoder_swallows_esphome_error() -> None: """A failing stack-trace decode must not propagate. - on_log runs inside an asyncio protocol callback; if EsphomeError - escapes, the loop reports "Fatal error: protocol.data_received() - call failed.", tears the connection down, and ReconnectLogic loops - forever as the device replays the same crash trace on every - reconnect. + aioesphomeapi isolates exceptions raised by log handlers, so an + escaping one logs a full traceback for every line it fires on rather + than being reported once as an unavailable decoder. """ config = {"esphome": {"name": "test"}} @@ -43,6 +41,32 @@ def test_decoder_swallows_platform_handler_error() -> None: assert processor.backtrace_state is False +def test_decoder_swallows_non_esphome_error() -> None: + """Decoding failures that aren't EsphomeError must be contained too. + + A missing build directory surfaces as FileNotFoundError from the toolchain + subprocess. aioesphomeapi isolates it, so the session survives, but it logs + a traceback for every PC/BT line and decoding is never disabled, which + buries the crash dump the user is trying to read. + """ + config = {"esphome": {"name": "test"}} + + with patch.object( + esp32, + "process_stacktrace", + side_effect=FileNotFoundError( + 2, "No such file or directory", "/build/ol/build" + ), + ) as mock_process: + processor = api_client._LogLineProcessor(config, esp32.process_stacktrace) + processor.process_line("PC: 0x4010496e") + processor.process_line("BT0: 0x4010496e") + + # Disabled after the first failure rather than retried per backtrace line. + assert mock_process.call_count == 1 + assert processor.backtrace_state is False + + def test_decoder_warning_uses_fallback_for_empty_error(caplog) -> None: """_run_idedata raises EsphomeError with no message; the warning must show a useful explanation rather than empty parens. @@ -61,7 +85,7 @@ def test_decoder_warning_uses_fallback_for_empty_error(caplog) -> None: def test_decoder_short_circuits_after_failure() -> None: """After one failure, subsequent lines must not retry the decoder. - _decode_pc shells out to PlatformIO; a crash dump can contain many + _decode_pc shells out to the toolchain; a crash dump can contain many PC/BT lines and retrying the failing subprocess for each one would stall log streaming. """ diff --git a/tests/unit_tests/test_espidf_toolchain.py b/tests/unit_tests/test_espidf_toolchain.py index e4b8971fb7..8731884ed3 100644 --- a/tests/unit_tests/test_espidf_toolchain.py +++ b/tests/unit_tests/test_espidf_toolchain.py @@ -5,12 +5,13 @@ import json import os from pathlib import Path +import subprocess from unittest.mock import patch import pytest from esphome.const import CONF_FRAMEWORK, CONF_SOURCE -from esphome.core import CORE +from esphome.core import CORE, EsphomeError from esphome.espidf import toolchain @@ -237,6 +238,77 @@ def test_get_idf_env_sets_git_ceiling_directories(setup_core: Path) -> None: assert str(CORE.config_dir) in env["GIT_CEILING_DIRECTORIES"].split(os.pathsep) +def test_get_cmake_output_without_build_dir(setup_core: Path) -> None: + """A build dir that was never created raises EsphomeError. + + Without this, subprocess.run(cwd=build_dir) raises FileNotFoundError, which + the log stack-trace decoder doesn't recognise as a decode failure. + """ + _setup_build(setup_core) + build_dir = CORE.relative_build_path("build") + assert not build_dir.exists() + + with pytest.raises(EsphomeError, match="No ESP-IDF build found"): + toolchain._get_cmake_output(build_dir) + + +def test_get_cmake_output_without_cmake_cache(setup_core: Path) -> None: + """A build dir that exists but was never configured raises EsphomeError.""" + _setup_build(setup_core) + build_dir = CORE.relative_build_path("build") + build_dir.mkdir(parents=True) + + with pytest.raises(EsphomeError, match="No ESP-IDF build found"): + toolchain._get_cmake_output(build_dir) + + +def test_get_cmake_output_with_configured_build(setup_core: Path) -> None: + """A configured build still runs cmake and caches the output. + + The missing-build guard must not get in the way of a real build. + """ + _setup_build(setup_core) + build_dir = CORE.relative_build_path("build") + build_dir.mkdir(parents=True) + (build_dir / "CMakeCache.txt").write_text("") + + completed = subprocess.CompletedProcess( + args=[], returncode=0, stdout="CMAKE_ADDR2LINE:FILEPATH=/tool/addr2line\n" + ) + with ( + patch.object(toolchain, "_get_idf_env", return_value={}), + patch.object(toolchain.subprocess, "run", return_value=completed) as mock_run, + ): + assert toolchain._get_cmake_output(build_dir) == completed.stdout + # Second call is served from the cache rather than re-running cmake. + assert toolchain._get_cmake_output(build_dir) == completed.stdout + + mock_run.assert_called_once() + assert toolchain._get_cmake_tool_path("CMAKE_ADDR2LINE") == Path("/tool/addr2line") + + +def test_get_cmake_output_missing_build_does_not_resolve_idf_env( + setup_core: Path, +) -> None: + """The build check runs before the env is resolved. + + Resolving the env calls check_esp_idf_install(), which can download and + extract the whole framework. A doomed call must never start that. + """ + _setup_build(setup_core) + build_dir = CORE.relative_build_path("build") + + with ( + patch.object(toolchain, "_get_idf_env") as mock_env, + patch.object(toolchain.subprocess, "run") as mock_run, + pytest.raises(EsphomeError), + ): + toolchain._get_cmake_output(build_dir) + + mock_env.assert_not_called() + mock_run.assert_not_called() + + def test_get_core_framework_version_from_core_data(): """The version is read from CORE.data when validation populated it.""" from esphome.components.esp32.const import KEY_ESP32, KEY_IDF_VERSION