From 9d87e8d02b68b96f16d56a9b5673ef9790147cec Mon Sep 17 00:00:00 2001 From: Erik Montnemery Date: Wed, 6 Sep 2023 10:03:35 +0200 Subject: [PATCH] Allow specifying a custom log function for template render (#99572) * Allow specifying a custom log function for template render * Bypass template cache when reporting errors + fix tests * Send errors as events * Fix logic for creating new TemplateEnvironment * Add strict mode back * Only send error events if report_errors is True * Force test of websocket_api only * Debug test * Run pytest with higher verbosity * Timeout after 1 minute, enable syslog output * Adjust timeout * Add debug logs * Fix unsafe call to WebSocketHandler._send_message * Remove debug code * Improve test coverage * Revert accidental change * Include severity in error events * Remove redundant information from error events --- .../components/websocket_api/commands.py | 32 +- homeassistant/helpers/event.py | 17 +- homeassistant/helpers/template.py | 113 ++++--- .../components/websocket_api/test_commands.py | 278 ++++++++++++++++-- tests/helpers/test_template.py | 18 +- 5 files changed, 374 insertions(+), 84 deletions(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index 84c7567a40e..7772bef66f9 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -5,6 +5,7 @@ from collections.abc import Callable import datetime as dt from functools import lru_cache, partial import json +import logging from typing import Any, cast import voluptuous as vol @@ -505,6 +506,7 @@ def _cached_template(template_str: str, hass: HomeAssistant) -> template.Templat vol.Optional("variables"): dict, vol.Optional("timeout"): vol.Coerce(float), vol.Optional("strict", default=False): bool, + vol.Optional("report_errors", default=False): bool, } ) @decorators.async_response @@ -513,14 +515,32 @@ async def handle_render_template( ) -> None: """Handle render_template command.""" template_str = msg["template"] - template_obj = _cached_template(template_str, hass) + report_errors: bool = msg["report_errors"] + if report_errors: + template_obj = template.Template(template_str, hass) + else: + template_obj = _cached_template(template_str, hass) variables = msg.get("variables") timeout = msg.get("timeout") + @callback + def _error_listener(level: int, template_error: str) -> None: + connection.send_message( + messages.event_message( + msg["id"], + {"error": template_error, "level": logging.getLevelName(level)}, + ) + ) + + @callback + def _thread_safe_error_listener(level: int, template_error: str) -> None: + hass.loop.call_soon_threadsafe(_error_listener, level, template_error) + if timeout: try: + log_fn = _thread_safe_error_listener if report_errors else None timed_out = await template_obj.async_render_will_timeout( - timeout, variables, strict=msg["strict"] + timeout, variables, strict=msg["strict"], log_fn=log_fn ) except TemplateError as ex: connection.send_error(msg["id"], const.ERR_TEMPLATE_ERROR, str(ex)) @@ -542,7 +562,11 @@ async def handle_render_template( track_template_result = updates.pop() result = track_template_result.result if isinstance(result, TemplateError): - connection.send_error(msg["id"], const.ERR_TEMPLATE_ERROR, str(result)) + if not report_errors: + return + connection.send_message( + messages.event_message(msg["id"], {"error": str(result)}) + ) return connection.send_message( @@ -552,12 +576,14 @@ async def handle_render_template( ) try: + log_fn = _error_listener if report_errors else None info = async_track_template_result( hass, [TrackTemplate(template_obj, variables)], _template_listener, raise_on_template_error=True, strict=msg["strict"], + log_fn=log_fn, ) except TemplateError as ex: connection.send_error(msg["id"], const.ERR_TEMPLATE_ERROR, str(ex)) diff --git a/homeassistant/helpers/event.py b/homeassistant/helpers/event.py index 62a3b91991d..173dd057f96 100644 --- a/homeassistant/helpers/event.py +++ b/homeassistant/helpers/event.py @@ -915,7 +915,12 @@ class TrackTemplateResultInfo: """Return the representation.""" return f"" - def async_setup(self, raise_on_template_error: bool, strict: bool = False) -> None: + def async_setup( + self, + raise_on_template_error: bool, + strict: bool = False, + log_fn: Callable[[int, str], None] | None = None, + ) -> None: """Activation of template tracking.""" block_render = False super_template = self._track_templates[0] if self._has_super_template else None @@ -925,7 +930,7 @@ class TrackTemplateResultInfo: template = super_template.template variables = super_template.variables self._info[template] = info = template.async_render_to_info( - variables, strict=strict + variables, strict=strict, log_fn=log_fn ) # If the super template did not render to True, don't update other templates @@ -946,7 +951,7 @@ class TrackTemplateResultInfo: template = track_template_.template variables = track_template_.variables self._info[template] = info = template.async_render_to_info( - variables, strict=strict + variables, strict=strict, log_fn=log_fn ) if info.exception: @@ -1233,6 +1238,7 @@ def async_track_template_result( action: TrackTemplateResultListener, raise_on_template_error: bool = False, strict: bool = False, + log_fn: Callable[[int, str], None] | None = None, has_super_template: bool = False, ) -> TrackTemplateResultInfo: """Add a listener that fires when the result of a template changes. @@ -1264,6 +1270,9 @@ def async_track_template_result( tracking. strict When set to True, raise on undefined variables. + log_fn + If not None, template error messages will logging by calling log_fn + instead of the normal logging facility. has_super_template When set to True, the first template will block rendering of other templates if it doesn't render as True. @@ -1274,7 +1283,7 @@ def async_track_template_result( """ tracker = TrackTemplateResultInfo(hass, track_templates, action, has_super_template) - tracker.async_setup(raise_on_template_error, strict=strict) + tracker.async_setup(raise_on_template_error, strict=strict, log_fn=log_fn) return tracker diff --git a/homeassistant/helpers/template.py b/homeassistant/helpers/template.py index b5a6a45e97f..9f280db6c98 100644 --- a/homeassistant/helpers/template.py +++ b/homeassistant/helpers/template.py @@ -458,6 +458,7 @@ class Template: "_exc_info", "_limited", "_strict", + "_log_fn", "_hash_cache", "_renders", ) @@ -475,6 +476,7 @@ class Template: self._exc_info: sys._OptExcInfo | None = None self._limited: bool | None = None self._strict: bool | None = None + self._log_fn: Callable[[int, str], None] | None = None self._hash_cache: int = hash(self.template) self._renders: int = 0 @@ -482,6 +484,11 @@ class Template: def _env(self) -> TemplateEnvironment: if self.hass is None: return _NO_HASS_ENV + # Bypass cache if a custom log function is specified + if self._log_fn is not None: + return TemplateEnvironment( + self.hass, self._limited, self._strict, self._log_fn + ) if self._limited: wanted_env = _ENVIRONMENT_LIMITED elif self._strict: @@ -491,9 +498,7 @@ class Template: ret: TemplateEnvironment | None = self.hass.data.get(wanted_env) if ret is None: ret = self.hass.data[wanted_env] = TemplateEnvironment( - self.hass, - self._limited, - self._strict, + self.hass, self._limited, self._strict, self._log_fn ) return ret @@ -537,6 +542,7 @@ class Template: parse_result: bool = True, limited: bool = False, strict: bool = False, + log_fn: Callable[[int, str], None] | None = None, **kwargs: Any, ) -> Any: """Render given template. @@ -553,7 +559,7 @@ class Template: return self.template return self._parse_result(self.template) - compiled = self._compiled or self._ensure_compiled(limited, strict) + compiled = self._compiled or self._ensure_compiled(limited, strict, log_fn) if variables is not None: kwargs.update(variables) @@ -608,6 +614,7 @@ class Template: timeout: float, variables: TemplateVarsType = None, strict: bool = False, + log_fn: Callable[[int, str], None] | None = None, **kwargs: Any, ) -> bool: """Check to see if rendering a template will timeout during render. @@ -628,7 +635,7 @@ class Template: if self.is_static: return False - compiled = self._compiled or self._ensure_compiled(strict=strict) + compiled = self._compiled or self._ensure_compiled(strict=strict, log_fn=log_fn) if variables is not None: kwargs.update(variables) @@ -664,7 +671,11 @@ class Template: @callback def async_render_to_info( - self, variables: TemplateVarsType = None, strict: bool = False, **kwargs: Any + self, + variables: TemplateVarsType = None, + strict: bool = False, + log_fn: Callable[[int, str], None] | None = None, + **kwargs: Any, ) -> RenderInfo: """Render the template and collect an entity filter.""" self._renders += 1 @@ -680,7 +691,9 @@ class Template: token = _render_info.set(render_info) try: - render_info._result = self.async_render(variables, strict=strict, **kwargs) + render_info._result = self.async_render( + variables, strict=strict, log_fn=log_fn, **kwargs + ) except TemplateError as ex: render_info.exception = ex finally: @@ -743,7 +756,10 @@ class Template: return value if error_value is _SENTINEL else error_value def _ensure_compiled( - self, limited: bool = False, strict: bool = False + self, + limited: bool = False, + strict: bool = False, + log_fn: Callable[[int, str], None] | None = None, ) -> jinja2.Template: """Bind a template to a specific hass instance.""" self.ensure_valid() @@ -756,10 +772,14 @@ class Template: self._strict is None or self._strict == strict ), "can't change between strict and non strict template" assert not (strict and limited), "can't combine strict and limited template" + assert ( + self._log_fn is None or self._log_fn == log_fn + ), "can't change custom log function" assert self._compiled_code is not None, "template code was not compiled" self._limited = limited self._strict = strict + self._log_fn = log_fn env = self._env self._compiled = jinja2.Template.from_code( @@ -2178,45 +2198,56 @@ def _render_with_context( return template.render(**kwargs) -class LoggingUndefined(jinja2.Undefined): +def make_logging_undefined( + strict: bool | None, log_fn: Callable[[int, str], None] | None +) -> type[jinja2.Undefined]: """Log on undefined variables.""" - def _log_message(self) -> None: + if strict: + return jinja2.StrictUndefined + + def _log_with_logger(level: int, msg: str) -> None: template, action = template_cv.get() or ("", "rendering or compiling") - _LOGGER.warning( - "Template variable warning: %s when %s '%s'", - self._undefined_message, + _LOGGER.log( + level, + "Template variable %s: %s when %s '%s'", + logging.getLevelName(level).lower(), + msg, action, template, ) - def _fail_with_undefined_error(self, *args, **kwargs): - try: - return super()._fail_with_undefined_error(*args, **kwargs) - except self._undefined_exception as ex: - template, action = template_cv.get() or ("", "rendering or compiling") - _LOGGER.error( - "Template variable error: %s when %s '%s'", - self._undefined_message, - action, - template, - ) - raise ex + _log_fn = log_fn or _log_with_logger - def __str__(self) -> str: - """Log undefined __str___.""" - self._log_message() - return super().__str__() + class LoggingUndefined(jinja2.Undefined): + """Log on undefined variables.""" - def __iter__(self): - """Log undefined __iter___.""" - self._log_message() - return super().__iter__() + def _log_message(self) -> None: + _log_fn(logging.WARNING, self._undefined_message) - def __bool__(self) -> bool: - """Log undefined __bool___.""" - self._log_message() - return super().__bool__() + def _fail_with_undefined_error(self, *args, **kwargs): + try: + return super()._fail_with_undefined_error(*args, **kwargs) + except self._undefined_exception as ex: + _log_fn(logging.ERROR, self._undefined_message) + raise ex + + def __str__(self) -> str: + """Log undefined __str___.""" + self._log_message() + return super().__str__() + + def __iter__(self): + """Log undefined __iter___.""" + self._log_message() + return super().__iter__() + + def __bool__(self) -> bool: + """Log undefined __bool___.""" + self._log_message() + return super().__bool__() + + return LoggingUndefined async def async_load_custom_templates(hass: HomeAssistant) -> None: @@ -2281,14 +2312,10 @@ class TemplateEnvironment(ImmutableSandboxedEnvironment): hass: HomeAssistant | None, limited: bool | None = False, strict: bool | None = False, + log_fn: Callable[[int, str], None] | None = None, ) -> None: """Initialise template environment.""" - undefined: type[LoggingUndefined] | type[jinja2.StrictUndefined] - if not strict: - undefined = LoggingUndefined - else: - undefined = jinja2.StrictUndefined - super().__init__(undefined=undefined) + super().__init__(undefined=make_logging_undefined(strict, log_fn)) self.hass = hass self.template_cache: weakref.WeakValueDictionary[ str | jinja2.nodes.Template, CodeType | str | None diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index 73baa968ab6..96e79a81716 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -2,6 +2,7 @@ import asyncio from copy import deepcopy import datetime +import logging from unittest.mock import ANY, AsyncMock, Mock, patch import pytest @@ -33,7 +34,11 @@ from tests.common import ( async_mock_service, mock_platform, ) -from tests.typing import ClientSessionGenerator, WebSocketGenerator +from tests.typing import ( + ClientSessionGenerator, + MockHAClientWebSocket, + WebSocketGenerator, +) STATE_KEY_SHORT_NAMES = { "entity_id": "e", @@ -1225,46 +1230,187 @@ async def test_render_template_manual_entity_ids_no_longer_needed( } +EMPTY_LISTENERS = {"all": False, "entities": [], "domains": [], "time": False} + +ERR_MSG = {"type": "result", "success": False} + +VARIABLE_ERROR_UNDEFINED_FUNC = { + "error": "'my_unknown_func' is undefined", + "level": "ERROR", +} +TEMPLATE_ERROR_UNDEFINED_FUNC = { + "code": "template_error", + "message": "UndefinedError: 'my_unknown_func' is undefined", +} + +VARIABLE_WARNING_UNDEFINED_VAR = { + "error": "'my_unknown_var' is undefined", + "level": "WARNING", +} +TEMPLATE_ERROR_UNDEFINED_VAR = { + "code": "template_error", + "message": "UndefinedError: 'my_unknown_var' is undefined", +} + +TEMPLATE_ERROR_UNDEFINED_FILTER = { + "code": "template_error", + "message": "TemplateAssertionError: No filter named 'unknown_filter'.", +} + + @pytest.mark.parametrize( - "template", + ("template", "expected_events"), [ - "{{ my_unknown_func() + 1 }}", - "{{ my_unknown_var }}", - "{{ my_unknown_var + 1 }}", - "{{ now() | unknown_filter }}", + ( + "{{ my_unknown_func() + 1 }}", + [ + {"type": "event", "event": VARIABLE_ERROR_UNDEFINED_FUNC}, + ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_FUNC}, + ], + ), + ( + "{{ my_unknown_var }}", + [ + {"type": "event", "event": VARIABLE_WARNING_UNDEFINED_VAR}, + {"type": "result", "success": True, "result": None}, + {"type": "event", "event": VARIABLE_WARNING_UNDEFINED_VAR}, + { + "type": "event", + "event": {"result": "", "listeners": EMPTY_LISTENERS}, + }, + ], + ), + ( + "{{ my_unknown_var + 1 }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_VAR}], + ), + ( + "{{ now() | unknown_filter }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_FILTER}], + ), ], ) async def test_render_template_with_error( - hass: HomeAssistant, websocket_client, caplog: pytest.LogCaptureFixture, template + hass: HomeAssistant, + websocket_client: MockHAClientWebSocket, + caplog: pytest.LogCaptureFixture, + template: str, + expected_events: list[dict[str, str]], ) -> None: """Test a template with an error.""" + caplog.set_level(logging.INFO) await websocket_client.send_json( - {"id": 5, "type": "render_template", "template": template, "strict": True} + { + "id": 5, + "type": "render_template", + "template": template, + "report_errors": True, + } ) - msg = await websocket_client.receive_json() - assert msg["id"] == 5 - assert msg["type"] == const.TYPE_RESULT - assert not msg["success"] - assert msg["error"]["code"] == const.ERR_TEMPLATE_ERROR + for expected_event in expected_events: + msg = await websocket_client.receive_json() + assert msg["id"] == 5 + for key, value in expected_event.items(): + assert msg[key] == value assert "Template variable error" not in caplog.text + assert "Template variable warning" not in caplog.text assert "TemplateError" not in caplog.text @pytest.mark.parametrize( - "template", + ("template", "expected_events"), [ - "{{ my_unknown_func() + 1 }}", - "{{ my_unknown_var }}", - "{{ my_unknown_var + 1 }}", - "{{ now() | unknown_filter }}", + ( + "{{ my_unknown_func() + 1 }}", + [ + {"type": "event", "event": VARIABLE_ERROR_UNDEFINED_FUNC}, + ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_FUNC}, + ], + ), + ( + "{{ my_unknown_var }}", + [ + {"type": "event", "event": VARIABLE_WARNING_UNDEFINED_VAR}, + {"type": "result", "success": True, "result": None}, + {"type": "event", "event": VARIABLE_WARNING_UNDEFINED_VAR}, + { + "type": "event", + "event": {"result": "", "listeners": EMPTY_LISTENERS}, + }, + ], + ), + ( + "{{ my_unknown_var + 1 }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_VAR}], + ), + ( + "{{ now() | unknown_filter }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_FILTER}], + ), ], ) async def test_render_template_with_timeout_and_error( - hass: HomeAssistant, websocket_client, caplog: pytest.LogCaptureFixture, template + hass: HomeAssistant, + websocket_client, + caplog: pytest.LogCaptureFixture, + template: str, + expected_events: list[dict[str, str]], ) -> None: """Test a template with an error with a timeout.""" + caplog.set_level(logging.INFO) + await websocket_client.send_json( + { + "id": 5, + "type": "render_template", + "template": template, + "timeout": 5, + "report_errors": True, + } + ) + + for expected_event in expected_events: + msg = await websocket_client.receive_json() + assert msg["id"] == 5 + for key, value in expected_event.items(): + assert msg[key] == value + + assert "Template variable error" not in caplog.text + assert "Template variable warning" not in caplog.text + assert "TemplateError" not in caplog.text + + +@pytest.mark.parametrize( + ("template", "expected_events"), + [ + ( + "{{ my_unknown_func() + 1 }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_FUNC}], + ), + ( + "{{ my_unknown_var }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_VAR}], + ), + ( + "{{ my_unknown_var + 1 }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_VAR}], + ), + ( + "{{ now() | unknown_filter }}", + [ERR_MSG | {"error": TEMPLATE_ERROR_UNDEFINED_FILTER}], + ), + ], +) +async def test_render_template_strict_with_timeout_and_error( + hass: HomeAssistant, + websocket_client, + caplog: pytest.LogCaptureFixture, + template: str, + expected_events: list[dict[str, str]], +) -> None: + """Test a template with an error with a timeout.""" + caplog.set_level(logging.INFO) await websocket_client.send_json( { "id": 5, @@ -1275,13 +1421,14 @@ async def test_render_template_with_timeout_and_error( } ) - msg = await websocket_client.receive_json() - assert msg["id"] == 5 - assert msg["type"] == const.TYPE_RESULT - assert not msg["success"] - assert msg["error"]["code"] == const.ERR_TEMPLATE_ERROR + for expected_event in expected_events: + msg = await websocket_client.receive_json() + assert msg["id"] == 5 + for key, value in expected_event.items(): + assert msg[key] == value assert "Template variable error" not in caplog.text + assert "Template variable warning" not in caplog.text assert "TemplateError" not in caplog.text @@ -1299,13 +1446,19 @@ async def test_render_template_error_in_template_code( assert not msg["success"] assert msg["error"]["code"] == const.ERR_TEMPLATE_ERROR + assert "Template variable error" not in caplog.text + assert "Template variable warning" not in caplog.text assert "TemplateError" not in caplog.text async def test_render_template_with_delayed_error( hass: HomeAssistant, websocket_client, caplog: pytest.LogCaptureFixture ) -> None: - """Test a template with an error that only happens after a state change.""" + """Test a template with an error that only happens after a state change. + + In this test report_errors is enabled. + """ + caplog.set_level(logging.INFO) hass.states.async_set("sensor.test", "on") await hass.async_block_till_done() @@ -1318,12 +1471,16 @@ async def test_render_template_with_delayed_error( """ await websocket_client.send_json( - {"id": 5, "type": "render_template", "template": template_str} + { + "id": 5, + "type": "render_template", + "template": template_str, + "report_errors": True, + } ) await hass.async_block_till_done() msg = await websocket_client.receive_json() - assert msg["id"] == 5 assert msg["type"] == const.TYPE_RESULT assert msg["success"] @@ -1347,13 +1504,74 @@ async def test_render_template_with_delayed_error( msg = await websocket_client.receive_json() assert msg["id"] == 5 - assert msg["type"] == const.TYPE_RESULT - assert not msg["success"] - assert msg["error"]["code"] == const.ERR_TEMPLATE_ERROR + assert msg["type"] == "event" + event = msg["event"] + assert event["error"] == "'None' has no attribute 'state'" + msg = await websocket_client.receive_json() + assert msg["id"] == 5 + assert msg["type"] == "event" + event = msg["event"] + assert event == {"error": "UndefinedError: 'explode' is undefined"} + + assert "Template variable error" not in caplog.text + assert "Template variable warning" not in caplog.text assert "TemplateError" not in caplog.text +async def test_render_template_with_delayed_error_2( + hass: HomeAssistant, websocket_client, caplog: pytest.LogCaptureFixture +) -> None: + """Test a template with an error that only happens after a state change. + + In this test report_errors is disabled. + """ + hass.states.async_set("sensor.test", "on") + await hass.async_block_till_done() + + template_str = """ +{% if states.sensor.test.state %} + on +{% else %} + {{ explode + 1 }} +{% endif %} + """ + + await websocket_client.send_json( + { + "id": 5, + "type": "render_template", + "template": template_str, + "report_errors": False, + } + ) + await hass.async_block_till_done() + + msg = await websocket_client.receive_json() + assert msg["id"] == 5 + assert msg["type"] == const.TYPE_RESULT + assert msg["success"] + + hass.states.async_remove("sensor.test") + await hass.async_block_till_done() + + msg = await websocket_client.receive_json() + assert msg["id"] == 5 + assert msg["type"] == "event" + event = msg["event"] + assert event == { + "result": "on", + "listeners": { + "all": False, + "domains": [], + "entities": ["sensor.test"], + "time": False, + }, + } + + assert "Template variable warning" in caplog.text + + async def test_render_template_with_timeout( hass: HomeAssistant, websocket_client, caplog: pytest.LogCaptureFixture ) -> None: diff --git a/tests/helpers/test_template.py b/tests/helpers/test_template.py index d14496d321e..58e0c730165 100644 --- a/tests/helpers/test_template.py +++ b/tests/helpers/test_template.py @@ -4466,15 +4466,25 @@ async def test_parse_result(hass: HomeAssistant) -> None: assert template.Template(tpl, hass).async_render() == result -async def test_undefined_variable( - hass: HomeAssistant, caplog: pytest.LogCaptureFixture +@pytest.mark.parametrize( + "template_string", + [ + "{{ no_such_variable }}", + "{{ no_such_variable and True }}", + "{{ no_such_variable | join(', ') }}", + ], +) +async def test_undefined_symbol_warnings( + hass: HomeAssistant, + caplog: pytest.LogCaptureFixture, + template_string: str, ) -> None: """Test a warning is logged on undefined variables.""" - tpl = template.Template("{{ no_such_variable }}", hass) + tpl = template.Template(template_string, hass) assert tpl.async_render() == "" assert ( "Template variable warning: 'no_such_variable' is undefined when rendering " - "'{{ no_such_variable }}'" in caplog.text + f"'{template_string}'" in caplog.text )