From 9f481e16422792b30ced30b3b0b884f091e23ec2 Mon Sep 17 00:00:00 2001 From: Erik Montnemery Date: Thu, 1 Apr 2021 18:42:23 +0200 Subject: [PATCH] Include script script_execution in script and automation traces (#48576) --- .../components/automation/__init__.py | 2 + homeassistant/components/trace/__init__.py | 4 + homeassistant/helpers/script.py | 13 +- homeassistant/helpers/trace.py | 27 +++ tests/components/trace/test_websocket_api.py | 166 +++++++++++++++++- tests/helpers/test_script.py | 36 ++-- 6 files changed, 228 insertions(+), 20 deletions(-) diff --git a/homeassistant/components/automation/__init__.py b/homeassistant/components/automation/__init__.py index 554b27fdb2f..6caa53dff79 100644 --- a/homeassistant/components/automation/__init__.py +++ b/homeassistant/components/automation/__init__.py @@ -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) diff --git a/homeassistant/components/trace/__init__.py b/homeassistant/components/trace/__init__.py index cdae44fff6b..c17cbf86715 100644 --- a/homeassistant/components/trace/__init__.py +++ b/homeassistant/components/trace/__init__.py @@ -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, diff --git a/homeassistant/helpers/script.py b/homeassistant/helpers/script.py index e342f0ff9a8..bf52fc81b6a 100644 --- a/homeassistant/helpers/script.py +++ b/homeassistant/helpers/script.py @@ -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 diff --git a/homeassistant/helpers/trace.py b/homeassistant/helpers/trace.py index 5d5a0f5ff03..c92766036c6 100644 --- a/homeassistant/helpers/trace.py +++ b/homeassistant/helpers/trace.py @@ -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. diff --git a/tests/components/trace/test_websocket_api.py b/tests/components/trace/test_websocket_api.py index 84d7100d1c8..8e481dd34b9 100644 --- a/tests/components/trace/test_websocket_api.py +++ b/tests/components/trace/test_websocket_api.py @@ -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" diff --git a/tests/helpers/test_script.py b/tests/helpers/test_script.py index e4170ccae20..7224dd70677 100644 --- a/tests/helpers/test_script.py +++ b/tests/helpers/test_script.py @@ -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):