Home-Assistant
/
core
mirror of https://github.com/home-assistant/core.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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
pull/99714/head
Erik Montnemery 2023-09-06 10:03:35 +02:00 committed by GitHub
parent f41b045244
commit 48f7924e9e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 374 additions and 84 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

32
homeassistant/components/websocket_api/commands.py
View File

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

17
homeassistant/helpers/event.py
View File

@ -915,7 +915,12 @@ class TrackTemplateResultInfo:
"""Return the representation."""
return f"<TrackTemplateResultInfo {self._info}>"
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

113
homeassistant/helpers/template.py
View File

@ -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

278
tests/components/websocket_api/test_commands.py
View File

@ -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:

18
tests/helpers/test_template.py
View File

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