Prevent log spam when WS subscribe_condition is active (#172832)

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

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,

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()

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"),
     [

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' }}"}