Reduce automation state changes by using script helper's last_triggered attribute (#39323)

homeassistant/components/automation/__init__.py

@@ -47,7 +47,7 @@ from homeassistant.helpers.service import async_register_admin_service
 from homeassistant.helpers.trigger import async_initialize_triggers
 from homeassistant.helpers.typing import TemplateVarsType
 from homeassistant.loader import bind_hass
-from homeassistant.util.dt import parse_datetime, utcnow
+from homeassistant.util.dt import parse_datetime
 
 # mypy: allow-untyped-calls, allow-untyped-defs
 # mypy: no-check-untyped-defs, no-warn-return-any
@@ -247,7 +247,6 @@ class AutomationEntity(ToggleEntity, RestoreEntity):
         self._cond_func = cond_func
         self.action_script = action_script
         self.action_script.change_listener = self.async_write_ha_state
-        self._last_triggered = None
         self._initial_state = initial_state
         self._is_enabled = False
         self._referenced_entities: Optional[Set[str]] = None
@@ -273,7 +272,7 @@ class AutomationEntity(ToggleEntity, RestoreEntity):
     def state_attributes(self):
         """Return the entity state attributes."""
         attrs = {
-            ATTR_LAST_TRIGGERED: self._last_triggered,
+            ATTR_LAST_TRIGGERED: self.action_script.last_triggered,
             ATTR_MODE: self.action_script.script_mode,
             ATTR_CUR: self.action_script.runs,
         }
@@ -339,7 +338,7 @@ class AutomationEntity(ToggleEntity, RestoreEntity):
             enable_automation = state.state == STATE_ON
             last_triggered = state.attributes.get("last_triggered")
             if last_triggered is not None:
-                self._last_triggered = parse_datetime(last_triggered)
+                self.action_script.last_triggered = parse_datetime(last_triggered)
             self._logger.debug(
                 "Loaded automation %s with state %s from state "
                 " storage last state %s",
@@ -395,22 +394,23 @@ class AutomationEntity(ToggleEntity, RestoreEntity):
         trigger_context = Context(parent_id=parent_id)
 
         self.async_set_context(trigger_context)
-        self._last_triggered = utcnow()
-        self.async_write_ha_state()
         event_data = {
             ATTR_NAME: self._name,
             ATTR_ENTITY_ID: self.entity_id,
         }
         if "trigger" in variables and "description" in variables["trigger"]:
             event_data[ATTR_SOURCE] = variables["trigger"]["description"]
-        self.hass.bus.async_fire(
-            EVENT_AUTOMATION_TRIGGERED, event_data, context=trigger_context
-        )
 
-        self._logger.info("Executing %s", self._name)
+        @callback
+        def started_action():
+            self.hass.bus.async_fire(
+                EVENT_AUTOMATION_TRIGGERED, event_data, context=trigger_context
+            )
 
         try:
-            await self.action_script.async_run(variables, trigger_context)
+            await self.action_script.async_run(
+                variables, trigger_context, started_action
+            )
         except Exception:  # pylint: disable=broad-except
             self._logger.exception("While executing automation %s", self.entity_id)
 

homeassistant/helpers/script.py

@@ -450,9 +450,7 @@ class _ScriptRun:
                 )
             except exceptions.TemplateError as ex:
                 self._log(
-                    "Error rendering event data template: %s",
+                    "Error rendering event data template: %s", ex, level=logging.ERROR
-                    ex,
-                    level=logging.ERROR,
                 )
 
         self._hass.bus.async_fire(
@@ -859,7 +857,10 @@ class Script:
         ).result()
 
     async def async_run(
-        self, variables: Optional[_VarsType] = None, context: Optional[Context] = None
+        self,
+        variables: Optional[_VarsType] = None,
+        context: Optional[Context] = None,
+        started_action: Optional[Callable[..., Any]] = None,
     ) -> None:
         """Run script."""
         if context is None:
@@ -894,6 +895,8 @@ class Script:
             self._hass, self, cast(dict, variables), context, self._log_exceptions
         )
         self._runs.append(run)
+        if started_action:
+            self._hass.async_run_job(started_action)
         self.last_triggered = utcnow()
         self._changed()
 

tests/components/automation/test_init.py

@@ -73,7 +73,7 @@ async def test_service_specify_data(hass, calls):
 
     time = dt_util.utcnow()
 
-    with patch("homeassistant.components.automation.utcnow", return_value=time):
+    with patch("homeassistant.helpers.script.utcnow", return_value=time):
         hass.bus.async_fire("test_event")
         await hass.async_block_till_done()
 
@@ -587,11 +587,7 @@ async def test_automation_stops(hass, calls, service):
             ],
         }
     }
-    assert await async_setup_component(
+    assert await async_setup_component(hass, automation.DOMAIN, config)
-        hass,
-        automation.DOMAIN,
-        config,
-    )
 
     running = asyncio.Event()
 

tests/helpers/test_script.py

@@ -1706,3 +1706,22 @@ async def test_update_logger(hass, caplog):
     await hass.async_block_till_done()
 
     assert log_name in caplog.text
+
+
+async def test_started_action(hass, caplog):
+    """Test the callback of started_action."""
+    event = "test_event"
+    log_message = "The script started!"
+    logger = logging.getLogger("TEST")
+
+    sequence = cv.SCRIPT_SCHEMA({"event": event})
+    script_obj = script.Script(hass, sequence, "Test Name", "test_domain")
+
+    @callback
+    def started_action():
+        logger.info(log_message)
+
+    await script_obj.async_run(context=Context(), started_action=started_action)
+    await hass.async_block_till_done()
+
+    assert log_message in caplog.text