diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index a1c466b9400f..0bcbad5b6275 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -39,6 +39,7 @@ from homeassistant.helpers import ( entity, target as target_helpers, template, + trace, ) from homeassistant.helpers.condition import ( async_from_config as async_condition_from_config, @@ -1061,10 +1062,24 @@ async def handle_subscribe_condition( nonlocal event_data new_event_data: dict[str, Any] + condition_trace = trace.trace_get() try: - new_event_data = {"result": condition.async_check()} + with trace.record_template_errors(): + new_event_data = {"result": condition.async_check()} except HomeAssistantError as err: new_event_data = {"error": str(err)} + + # Template errors (e.g. undefined variables) are recorded in the trace + # instead of being logged. Forward them to the client so they are not + # lost, even when the condition still evaluated to a result. + if template_errors := [ + template_error + for elements in condition_trace.values() + for element in elements + for template_error in element.template_errors + ]: + new_event_data["template_errors"] = template_errors + if new_event_data == event_data: return event_data = new_event_data diff --git a/homeassistant/helpers/template/__init__.py b/homeassistant/helpers/template/__init__.py index ba1fe3b1fc12..7bd5c16000f4 100644 --- a/homeassistant/helpers/template/__init__.py +++ b/homeassistant/helpers/template/__init__.py @@ -24,6 +24,11 @@ from homeassistant.const import EVENT_HOMEASSISTANT_START, EVENT_HOMEASSISTANT_S from homeassistant.core import HomeAssistant, callback from homeassistant.exceptions import TemplateError from homeassistant.helpers.singleton import singleton +from homeassistant.helpers.trace import ( + record_template_errors_cv, + trace_stack_cv, + trace_stack_top, +) from homeassistant.helpers.typing import TemplateVarsType from homeassistant.util.async_ import run_callback_threadsafe from homeassistant.util.hass_dict import HassKey @@ -627,6 +632,15 @@ def make_logging_undefined( return jinja2.StrictUndefined def _log_with_logger(level: int, msg: str) -> None: + # When a consumer such as the subscribe_condition websocket command has + # opted in, record the error on the active trace element instead of + # logging it, so repeated evaluations don't spam the log. + if record_template_errors_cv.get() and ( + node := trace_stack_top(trace_stack_cv) + ): + node.add_template_error(msg) + return + template, action = template_cv.get() or ("", "rendering or compiling") _LOGGER.log( level, diff --git a/homeassistant/helpers/trace.py b/homeassistant/helpers/trace.py index e16bf0882233..8b21a87fb66c 100644 --- a/homeassistant/helpers/trace.py +++ b/homeassistant/helpers/trace.py @@ -5,7 +5,7 @@ from collections.abc import Callable, Coroutine, Generator from contextlib import contextmanager from contextvars import ContextVar from functools import wraps -from typing import Any +from typing import Any, Literal, overload from homeassistant.core import ServiceResponse from homeassistant.util import dt as dt_util @@ -22,6 +22,7 @@ class TraceElement: "_error", "_last_variables", "_result", + "_template_errors", "_timestamp", "_variables", "path", @@ -35,6 +36,7 @@ class TraceElement: self._error: BaseException | None = None self.path: str = path self._result: dict[str, Any] | None = None + self._template_errors: list[str] | None = None self.reuse_by_child = False self._timestamp = dt_util.utcnow() @@ -54,6 +56,23 @@ class TraceElement: """Set error.""" self._error = ex + def add_template_error(self, msg: str) -> None: + """Record a template error message. + + Used to record template variable errors which would otherwise be logged + directly, so they are surfaced in the trace instead of spamming the log. + A single template render can emit more than one message, so they are + accumulated in a list. + """ + if self._template_errors is None: + self._template_errors = [] + self._template_errors.append(msg) + + @property + def template_errors(self) -> list[str]: + """Return the recorded template error messages.""" + return self._template_errors or [] + def set_result(self, **kwargs: Any) -> None: """Set result.""" self._result = {**kwargs} @@ -90,6 +109,8 @@ class TraceElement: result["changed_variables"] = self._variables if self._error is not None: result["error"] = str(self._error) or self._error.__class__.__name__ + if self._template_errors: + result["template_errors"] = self._template_errors if self._result is not None: result["result"] = self._result return result @@ -118,6 +139,26 @@ trace_id_cv: ContextVar[tuple[str, str] | None] = ContextVar( script_execution_cv: ContextVar[StopReason | None] = ContextVar( "script_execution_cv", default=None ) +# When set, template errors are recorded on the active TraceElement instead of +# being logged directly +record_template_errors_cv: ContextVar[bool] = ContextVar( + "record_template_errors_cv", default=False +) + + +@contextmanager +def record_template_errors() -> Generator[None]: + """Record template errors in the active trace instead of logging them. + + Used by consumers such as the subscribe_condition websocket command, which + re-evaluate a condition repeatedly and forward template errors to the client + via the trace, so the errors don't spam the log. + """ + token = record_template_errors_cv.set(True) + try: + yield + finally: + record_template_errors_cv.reset(token) def trace_id_set(trace_id: tuple[str, str]) -> None: @@ -189,8 +230,23 @@ def trace_append_element( trace[path].append(trace_element) +@overload +def trace_get(clear: Literal[True] = True) -> dict[str, deque[TraceElement]]: ... + + +@overload +def trace_get(clear: Literal[False]) -> dict[str, deque[TraceElement]] | None: ... + + def trace_get(clear: bool = True) -> dict[str, deque[TraceElement]] | None: - """Return the current trace.""" + """Return the current trace. + + When clear is True the trace is reset and a fresh (empty) trace is + unconditionally returned. + + When clear is False, the current trace is returned without modification + if it exists, otherwise None is returned. + """ if clear: trace_clear() return trace_cv.get() diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index e2f76d330f12..dc96bec45710 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -2868,6 +2868,83 @@ async def test_subscribe_condition( } +@pytest.mark.parametrize( + ("value_template", "expected_event"), + [ + # Undefined variable used in a way that raises: forwarded as an error, + # with the underlying template error included. + ( + "{{ trigger.to_state.attributes.event_type == 'double_press' }}", + { + "error": "In 'template' condition: UndefinedError: 'trigger' is undefined", + "template_errors": ["'trigger' is undefined"], + }, + ), + # Undefined variable used in a way that only warns: the condition still + # evaluates to a result, but the template error is forwarded alongside it. + ( + "{{ no_such_variable }}", + {"result": False, "template_errors": ["'no_such_variable' is undefined"]}, + ), + # A single render emitting multiple errors forwards all of them. + ( + "{{ foo }}{{ bar }}", + { + "result": False, + "template_errors": ["'foo' is undefined", "'bar' is undefined"], + }, + ), + ], +) +async def test_subscribe_condition_template_error( + hass: HomeAssistant, + websocket_client: MockHAClientWebSocket, + freezer: FrozenDateTimeFactory, + caplog: pytest.LogCaptureFixture, + value_template: str, + expected_event: dict[str, Any], +) -> None: + """Test template errors are forwarded as events and don't spam the log.""" + caplog.set_level(logging.WARNING) + + await websocket_client.send_json_auto_id( + { + "type": "subscribe_condition", + "condition": { + "condition": "template", + "value_template": value_template, + }, + } + ) + + msg = await websocket_client.receive_json() + assert msg["type"] == const.TYPE_RESULT + assert msg["success"] + + subscription_id = msg["id"] + + msg = await websocket_client.receive_json() + assert msg == { + "id": subscription_id, + "type": "event", + "event": expected_event, + } + + # Let the condition be evaluated a few more times + for _ in range(5): + freezer.tick(1.1) + await hass.async_block_till_done() + + # The unchanged result/error is not re-sent; a ping is the next message + await websocket_client.send_json_auto_id({"type": "ping"}) + msg = await websocket_client.receive_json() + assert msg["type"] == "pong" + + # The template error is forwarded, not logged + assert "Template variable warning" not in caplog.text + assert "Template variable error" not in caplog.text + + @pytest.mark.parametrize( ("condition", "expected_error"), [ diff --git a/tests/helpers/test_condition.py b/tests/helpers/test_condition.py index 2e4146213ac4..6fd2c9b11730 100644 --- a/tests/helpers/test_condition.py +++ b/tests/helpers/test_condition.py @@ -2205,6 +2205,90 @@ async def test_condition_template_error(hass: HomeAssistant) -> None: test.async_check() +@pytest.mark.parametrize( + ("value_template", "expectation", "expected_template_errors", "expected_result"), + [ + # Undefined variable used in a way that raises (e.g. attribute access) + ( + "{{ trigger.to_state.attributes.event_type == 'double_press' }}", + pytest.raises(ConditionError), + ["'trigger' is undefined"], + {}, + ), + # Undefined variable used in a way that only warns + ( + "{{ no_such_variable }}", + does_not_raise(), + ["'no_such_variable' is undefined"], + {"result": False, "entities": []}, + ), + # A single render can emit more than one message + ( + "{{ foo }}{{ bar }}", + does_not_raise(), + ["'foo' is undefined", "'bar' is undefined"], + {"result": False, "entities": []}, + ), + ], +) +async def test_condition_template_error_traced_not_logged( + hass: HomeAssistant, + caplog: pytest.LogCaptureFixture, + value_template: str, + expectation: AbstractContextManager, + expected_template_errors: list[str], + expected_result: dict[str, Any], +) -> None: + """Test template errors are added to the trace and not logged when opted in. + + The subscribe_condition websocket command re-evaluates a condition every + second and opts in via trace.record_template_errors(). Template variable + errors must then be recorded in the trace instead of being logged repeatedly. + """ + caplog.set_level(logging.WARNING) + config = {"condition": "template", "value_template": value_template} + config = cv.CONDITION_SCHEMA(config) + config = await condition.async_validate_condition_config(hass, config) + test = await condition.async_from_config(hass, config) + + with expectation, trace.record_template_errors(): + test.async_check() + + # The template errors are recorded in the trace... + condition_trace = trace.trace_get(clear=False) + trace.trace_clear() + trace_element = condition_trace[""][0] + assert trace_element.template_errors == expected_template_errors + assert (trace_element._result or {}) == expected_result + + # ...and not logged + assert "Template variable" not in caplog.text + + +async def test_condition_template_error_logged_without_opt_in( + hass: HomeAssistant, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test template errors are logged when recording is not opted in. + + An active trace is not enough to suppress logging; the consumer must opt in + via trace.record_template_errors(). Without it, the error is logged as usual + and not recorded in the trace. + """ + caplog.set_level(logging.WARNING) + config = {"condition": "template", "value_template": "{{ no_such_variable }}"} + config = cv.CONDITION_SCHEMA(config) + config = await condition.async_validate_condition_config(hass, config) + test = await condition.async_from_config(hass, config) + + assert test.async_check() is False + + assert "Template variable warning: 'no_such_variable' is undefined" in caplog.text + condition_trace = trace.trace_get(clear=False) + trace.trace_clear() + assert condition_trace[""][0].template_errors == [] + + async def test_condition_template_invalid_results(hass: HomeAssistant) -> None: """Test template condition render false with invalid results.""" config = {"condition": "template", "value_template": "{{ 'string' }}"}