mirror of
https://github.com/esphome/esphome.git
synced 2026-08-23 06:36:23 +00:00
[api] Don't spam tracebacks when decoding a crash without a local build (#17597)
This commit is contained in:
@@ -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.",
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
@@ -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()
|
||||
|
||||
@@ -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.
|
||||
"""
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user