evlli/hass-core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Include script script_execution in script and automation traces (#48576)

Browse source
This commit is contained in:
Erik Montnemery 2021-04-01 18:42:23 +02:00 • committed by GitHub
parent 9d085778c2
commit 9f481e1642
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
6 changed files with 228 additions and 20 deletions
Download patch file Download diff file Expand all files Collapse all files

2
homeassistant/components/automation/__init__.py
View file

@ -57,6 +57,7 @@ from homeassistant.helpers.script_variables import ScriptVariables
from homeassistant.helpers.service import async_register_admin_service
from homeassistant.helpers.trace import (
TraceElement,
script_execution_set,
trace_append_element,
trace_get,
trace_path,
@ -471,6 +472,7 @@ class AutomationEntity(ToggleEntity, RestoreEntity):
"Conditions not met, aborting automation. Condition summary: %s",
trace_get(clear=False),
)
script_execution_set("failed_conditions")
return
self.async_set_context(trigger_context)

4
homeassistant/components/trace/__init__.py
View file

@ -8,6 +8,7 @@ from typing import Any, Deque
from homeassistant.core import Context
from homeassistant.helpers.trace import (
TraceElement,
script_execution_get,
trace_id_get,
trace_id_set,
trace_set_child_id,
@ -55,6 +56,7 @@ class ActionTrace:
self.context: Context = context
self._error: Exception | None = None
self._state: str = "running"
self._script_execution: str | None = None
self.run_id: str = str(next(self._run_ids))
self._timestamp_finish: dt.datetime | None = None
self._timestamp_start: dt.datetime = dt_util.utcnow()
@ -75,6 +77,7 @@ class ActionTrace:
"""Set finish time."""
self._timestamp_finish = dt_util.utcnow()
self._state = "stopped"
self._script_execution = script_execution_get()
def as_dict(self) -> dict[str, Any]:
"""Return dictionary version of this ActionTrace."""
@ -109,6 +112,7 @@ class ActionTrace:
"last_step": last_step,
"run_id": self.run_id,
"state": self._state,
"script_execution": self._script_execution,
"timestamp": {
"start": self._timestamp_start,
"finish": self._timestamp_finish,

13
homeassistant/helpers/script.py
View file

@ -63,6 +63,7 @@ from homeassistant.helpers.dispatcher import (
)
from homeassistant.helpers.event import async_call_later, async_track_template
from homeassistant.helpers.script_variables import ScriptVariables
from homeassistant.helpers.trace import script_execution_set
from homeassistant.helpers.trigger import (
async_initialize_triggers,
async_validate_trigger_config,
@ -332,15 +333,19 @@ class _ScriptRun:
async def async_run(self) -> None:
"""Run script."""
try:
if self._stop.is_set():
return
self._log("Running %s", self._script.running_description)
for self._step, self._action in enumerate(self._script.sequence):
if self._stop.is_set():
script_execution_set("cancelled")
break
await self._async_step(log_exceptions=False)
else:
script_execution_set("finished")
except _StopScript:
pass
script_execution_set("aborted")
except Exception:
script_execution_set("error")
raise
finally:
self._finish()
@ -1137,6 +1142,7 @@ class Script:
if self.script_mode == SCRIPT_MODE_SINGLE:
if self._max_exceeded != "SILENT":
self._log("Already running", level=LOGSEVERITY[self._max_exceeded])
script_execution_set("failed_single")
return
if self.script_mode == SCRIPT_MODE_RESTART:
self._log("Restarting")
@ -1147,6 +1153,7 @@ class Script:
"Maximum number of runs exceeded",
level=LOGSEVERITY[self._max_exceeded],
)
script_execution_set("failed_max_runs")
return
# If this is a top level Script then make a copy of the variables in case they

27
homeassistant/helpers/trace.py
View file

@ -88,6 +88,10 @@ variables_cv: ContextVar[Any | None] = ContextVar("variables_cv", default=None)
trace_id_cv: ContextVar[tuple[str, str] | None] = ContextVar(
"trace_id_cv", default=None
)
# Reason for stopped script execution
script_execution_cv: ContextVar[StopReason | None] = ContextVar(
"script_execution_cv", default=None
)
def trace_id_set(trace_id: tuple[str, str]) -> None:
@ -172,6 +176,7 @@ def trace_clear() -> None:
trace_stack_cv.set(None)
trace_path_stack_cv.set(None)
variables_cv.set(None)
script_execution_cv.set(StopReason())
def trace_set_child_id(child_key: tuple[str, str], child_run_id: str) -> None:
@ -187,6 +192,28 @@ def trace_set_result(**kwargs: Any) -> None:
node.set_result(**kwargs)
class StopReason:
"""Mutable container class for script_execution."""
script_execution: str | None = None
def script_execution_set(reason: str) -> None:
"""Set stop reason."""
data = script_execution_cv.get()
if data is None:
return
data.script_execution = reason
def script_execution_get() -> str | None:
"""Return the current trace."""
data = script_execution_cv.get()
if data is None:
return None
return data.script_execution
@contextmanager
def trace_path(suffix: str | list[str]) -> Generator:
"""Go deeper in the config tree.

166
tests/components/trace/test_websocket_api.py
View file

@ -1,9 +1,11 @@
"""Test Trace websocket API."""
import asyncio
import pytest
from homeassistant.bootstrap import async_setup_component
from homeassistant.components.trace.const import STORED_TRACES
from homeassistant.core import Context
from homeassistant.core import Context, callback
from homeassistant.helpers.typing import UNDEFINED
from tests.common import assert_lists_same
@ -170,6 +172,7 @@ async def test_get_trace(
assert trace["context"]
assert trace["error"] == "Unable to find service test.automation"
assert trace["state"] == "stopped"
assert trace["script_execution"] == "error"
assert trace["item_id"] == "sun"
assert trace["context"][context_key] == context.id
assert trace.get("trigger", UNDEFINED) == trigger[0]
@ -210,6 +213,7 @@ async def test_get_trace(
assert trace["context"]
assert "error" not in trace
assert trace["state"] == "stopped"
assert trace["script_execution"] == "finished"
assert trace["item_id"] == "moon"
assert trace.get("trigger", UNDEFINED) == trigger[1]
@ -260,6 +264,7 @@ async def test_get_trace(
assert trace["context"]
assert "error" not in trace
assert trace["state"] == "stopped"
assert trace["script_execution"] == "failed_conditions"
assert trace["trigger"] == "event 'test_event3'"
assert trace["item_id"] == "moon"
contexts[trace["context"]["id"]] = {
@ -301,6 +306,7 @@ async def test_get_trace(
assert trace["context"]
assert "error" not in trace
assert trace["state"] == "stopped"
assert trace["script_execution"] == "finished"
assert trace["trigger"] == "event 'test_event2'"
assert trace["item_id"] == "moon"
contexts[trace["context"]["id"]] = {
@ -391,7 +397,7 @@ async def test_trace_overflow(hass, hass_ws_client, domain):
@pytest.mark.parametrize(
"domain, prefix, trigger, last_step",
"domain, prefix, trigger, last_step, script_execution",
[
(
"automation",
@ -403,16 +409,20 @@ async def test_trace_overflow(hass, hass_ws_client, domain):
"event 'test_event2'",
],
["{prefix}/0", "{prefix}/0", "condition/0", "{prefix}/0"],
["error", "finished", "failed_conditions", "finished"],
),
(
"script",
"sequence",
[UNDEFINED, UNDEFINED, UNDEFINED, UNDEFINED],
["{prefix}/0", "{prefix}/0", "{prefix}/0", "{prefix}/0"],
["error", "finished", "finished", "finished"],
),
],
)
async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_step):
async def test_list_traces(
hass, hass_ws_client, domain, prefix, trigger, last_step, script_execution
):
"""Test listing script and automation traces."""
id = 1
@ -458,7 +468,7 @@ async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_s
await _run_automation_or_script(hass, domain, sun_config, "test_event")
await hass.async_block_till_done()
# Get trace
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": domain})
response = await client.receive_json()
assert response["success"]
@ -492,7 +502,7 @@ async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_s
await _run_automation_or_script(hass, domain, moon_config, "test_event2")
await hass.async_block_till_done()
# Get trace
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": domain})
response = await client.receive_json()
assert response["success"]
@ -502,6 +512,7 @@ async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_s
assert trace["last_step"] == last_step[0].format(prefix=prefix)
assert trace["error"] == "Unable to find service test.automation"
assert trace["state"] == "stopped"
assert trace["script_execution"] == script_execution[0]
assert trace["timestamp"]
assert trace["item_id"] == "sun"
assert trace.get("trigger", UNDEFINED) == trigger[0]
@ -510,6 +521,7 @@ async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_s
assert trace["last_step"] == last_step[1].format(prefix=prefix)
assert "error" not in trace
assert trace["state"] == "stopped"
assert trace["script_execution"] == script_execution[1]
assert trace["timestamp"]
assert trace["item_id"] == "moon"
assert trace.get("trigger", UNDEFINED) == trigger[1]
@ -518,6 +530,7 @@ async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_s
assert trace["last_step"] == last_step[2].format(prefix=prefix)
assert "error" not in trace
assert trace["state"] == "stopped"
assert trace["script_execution"] == script_execution[2]
assert trace["timestamp"]
assert trace["item_id"] == "moon"
assert trace.get("trigger", UNDEFINED) == trigger[2]
@ -526,6 +539,7 @@ async def test_list_traces(hass, hass_ws_client, domain, prefix, trigger, last_s
assert trace["last_step"] == last_step[3].format(prefix=prefix)
assert "error" not in trace
assert trace["state"] == "stopped"
assert trace["script_execution"] == script_execution[3]
assert trace["timestamp"]
assert trace["item_id"] == "moon"
assert trace.get("trigger", UNDEFINED) == trigger[3]
@ -1006,3 +1020,145 @@ async def test_breakpoints_3(hass, hass_ws_client, domain, prefix):
"node": f"{prefix}/5",
"run_id": run_id,
}
@pytest.mark.parametrize(
"script_mode,max_runs,script_execution",
[
({"mode": "single"}, 1, "failed_single"),
({"mode": "parallel", "max": 2}, 2, "failed_max_runs"),
],
)
async def test_script_mode(
hass, hass_ws_client, script_mode, max_runs, script_execution
):
"""Test overlapping runs with max_runs > 1."""
id = 1
def next_id():
nonlocal id
id += 1
return id
flag = asyncio.Event()
@callback
def _handle_event(_):
flag.set()
event = "test_event"
script_config = {
"script1": {
"sequence": [
{"event": event, "event_data": {"value": 1}},
{"wait_template": "{{ states.switch.test.state == 'off' }}"},
{"event": event, "event_data": {"value": 2}},
],
**script_mode,
},
}
client = await hass_ws_client()
hass.bus.async_listen(event, _handle_event)
assert await async_setup_component(hass, "script", {"script": script_config})
for _ in range(max_runs):
hass.states.async_set("switch.test", "on")
await hass.services.async_call("script", "script1")
await asyncio.wait_for(flag.wait(), 1)
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": "script"})
response = await client.receive_json()
assert response["success"]
traces = _find_traces(response["result"], "script", "script1")
assert len(traces) == max_runs
for trace in traces:
assert trace["state"] == "running"
# Start additional run of script while first runs are suspended in wait_template.
flag.clear()
await hass.services.async_call("script", "script1")
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": "script"})
response = await client.receive_json()
assert response["success"]
traces = _find_traces(response["result"], "script", "script1")
assert len(traces) == max_runs + 1
assert traces[-1]["state"] == "stopped"
assert traces[-1]["script_execution"] == script_execution
@pytest.mark.parametrize(
"script_mode,script_execution",
[("restart", "cancelled"), ("parallel", "finished")],
)
async def test_script_mode_2(hass, hass_ws_client, script_mode, script_execution):
"""Test overlapping runs with max_runs > 1."""
id = 1
def next_id():
nonlocal id
id += 1
return id
flag = asyncio.Event()
@callback
def _handle_event(_):
flag.set()
event = "test_event"
script_config = {
"script1": {
"sequence": [
{"event": event, "event_data": {"value": 1}},
{"wait_template": "{{ states.switch.test.state == 'off' }}"},
{"event": event, "event_data": {"value": 2}},
],
"mode": script_mode,
}
}
client = await hass_ws_client()
hass.bus.async_listen(event, _handle_event)
assert await async_setup_component(hass, "script", {"script": script_config})
hass.states.async_set("switch.test", "on")
await hass.services.async_call("script", "script1")
await asyncio.wait_for(flag.wait(), 1)
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": "script"})
response = await client.receive_json()
assert response["success"]
trace = _find_traces(response["result"], "script", "script1")[0]
assert trace["state"] == "running"
# Start second run of script while first run is suspended in wait_template.
flag.clear()
await hass.services.async_call("script", "script1")
await asyncio.wait_for(flag.wait(), 1)
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": "script"})
response = await client.receive_json()
assert response["success"]
trace = _find_traces(response["result"], "script", "script1")[1]
assert trace["state"] == "running"
# Let both scripts finish
hass.states.async_set("switch.test", "off")
await hass.async_block_till_done()
# List traces
await client.send_json({"id": next_id(), "type": "trace/list", "domain": "script"})
response = await client.receive_json()
assert response["success"]
trace = _find_traces(response["result"], "script", "script1")[0]
assert trace["state"] == "stopped"
assert trace["script_execution"] == script_execution
trace = _find_traces(response["result"], "script", "script1")[1]
assert trace["state"] == "stopped"
assert trace["script_execution"] == "finished"

36
tests/helpers/test_script.py
View file

@ -86,9 +86,10 @@ def assert_element(trace_element, expected_element, path):
assert not trace_element._variables
def assert_action_trace(expected):
def assert_action_trace(expected, expected_script_execution="finished"):
"""Assert a trace condition sequence is as expected."""
action_trace = trace.trace_get(clear=False)
script_execution = trace.script_execution_get()
trace.trace_clear()
expected_trace_keys = list(expected.keys())
assert list(action_trace.keys()) == expected_trace_keys
@ -98,6 +99,8 @@ def assert_action_trace(expected):
path = f"[{trace_key_index}][{index}]"
assert_element(action_trace[key][index], element, path)
assert script_execution == expected_script_execution
def async_watch_for_action(script_obj, message):
"""Watch for message in last_action."""
@ -620,7 +623,8 @@ async def test_delay_template_invalid(hass, caplog):
{
"0": [{"result": {"event": "test_event", "event_data": {}}}],
"1": [{"error_type": script._StopScript}],
}
},
expected_script_execution="aborted",
)
@ -680,7 +684,8 @@ async def test_delay_template_complex_invalid(hass, caplog):
{
"0": [{"result": {"event": "test_event", "event_data": {}}}],
"1": [{"error_type": script._StopScript}],
}
},
expected_script_execution="aborted",
)
@ -717,7 +722,8 @@ async def test_cancel_delay(hass):
assert_action_trace(
{
"0": [{"result": {"delay": 5.0, "done": False}}],
}
},
expected_script_execution="cancelled",
)
@ -969,13 +975,15 @@ async def test_cancel_wait(hass, action_type):
assert_action_trace(
{
"0": [{"result": {"wait": {"completed": False, "remaining": None}}}],
}
},
expected_script_execution="cancelled",
)
else:
assert_action_trace(
{
"0": [{"result": {"wait": {"trigger": None, "remaining": None}}}],
}
},
expected_script_execution="cancelled",
)
@ -1131,6 +1139,7 @@ async def test_wait_continue_on_timeout(
if continue_on_timeout is False:
expected_trace["0"][0]["result"]["timeout"] = True
expected_trace["0"][0]["error_type"] = script._StopScript
expected_script_execution = "aborted"
else:
expected_trace["1"] = [
{
@ -1138,7 +1147,8 @@ async def test_wait_continue_on_timeout(
"variables": variable_wait,
}
]
assert_action_trace(expected_trace)
expected_script_execution = "finished"
assert_action_trace(expected_trace, expected_script_execution)
async def test_wait_template_variables_in(hass):
@ -1404,7 +1414,8 @@ async def test_condition_warning(hass, caplog):
"1": [{"error_type": script._StopScript, "result": {"result": False}}],
"1/condition": [{"error_type": ConditionError}],
"1/condition/entity_id/0": [{"error_type": ConditionError}],
}
},
expected_script_execution="aborted",
)
@ -1456,7 +1467,8 @@ async def test_condition_basic(hass, caplog):
"0": [{"result": {"event": "test_event", "event_data": {}}}],
"1": [{"error_type": script._StopScript, "result": {"result": False}}],
"1/condition": [{"result": {"result": False}}],
}
},
expected_script_execution="aborted",
)
@ -2141,7 +2153,7 @@ async def test_propagate_error_service_not_found(hass):
}
],
}
assert_action_trace(expected_trace)
assert_action_trace(expected_trace, expected_script_execution="error")
async def test_propagate_error_invalid_service_data(hass):
@ -2178,7 +2190,7 @@ async def test_propagate_error_invalid_service_data(hass):
}
],
}
assert_action_trace(expected_trace)
assert_action_trace(expected_trace, expected_script_execution="error")
async def test_propagate_error_service_exception(hass):
@ -2219,7 +2231,7 @@ async def test_propagate_error_service_exception(hass):
}
],
}
assert_action_trace(expected_trace)
assert_action_trace(expected_trace, expected_script_execution="error")
async def test_referenced_entities(hass):