Make automations log errors (#18965)

homeassistant/components/automation/__init__.py

@@ -375,7 +375,15 @@ def _async_get_action(hass, config, name):
     async def action(entity_id, variables, context):
         """Execute an action."""
         _LOGGER.info('Executing %s', name)
+        hass.components.logbook.async_log_entry(
+            name, 'has been triggered', DOMAIN, entity_id)
+
+        try:
             await script_obj.async_run(variables, context)
+        except Exception as err:  # pylint: disable=broad-except
+            script_obj.async_log_exception(
+                _LOGGER,
+                'Error while executing automation {}'.format(entity_id), err)
 
     return action
 

homeassistant/helpers/script.py

@@ -85,6 +85,7 @@ class Script():
         self.name = name
         self._change_listener = change_listener
         self._cur = -1
+        self._exception_step = None
         self.last_action = None
         self.last_triggered = None
         self.can_cancel = any(CONF_DELAY in action or CONF_WAIT_TEMPLATE
@@ -136,10 +137,9 @@ class Script():
                 return
             except _StopScript:
                 break
-            except Exception as err:
+            except Exception:
                 # Store the step that had an exception
-                # pylint: disable=protected-access
-                err._script_step = cur
+                self._exception_step = cur
                 # Set script to not running
                 self._cur = -1
                 self.last_action = None
@@ -166,6 +166,44 @@ class Script():
         if self._change_listener:
             self.hass.async_add_job(self._change_listener)
 
+    @callback
+    def async_log_exception(self, logger, message_base, exception):
+        """Log an exception for this script.
+
+        Should only be called on exceptions raised by this scripts async_run.
+        """
+        # pylint: disable=protected-access
+        step = self._exception_step
+        action = self.sequence[step]
+        action_type = _determine_action(action)
+
+        error = None
+        meth = logger.error
+
+        if isinstance(exception, vol.Invalid):
+            error_desc = "Invalid data"
+
+        elif isinstance(exception, exceptions.TemplateError):
+            error_desc = "Error rendering template"
+
+        elif isinstance(exception, exceptions.Unauthorized):
+            error_desc = "Unauthorized"
+
+        elif isinstance(exception, exceptions.ServiceNotFound):
+            error_desc = "Service not found"
+
+        else:
+            # Print the full stack trace, unknown error
+            error_desc = 'Unknown error'
+            meth = logger.exception
+            error = ""
+
+        if error is None:
+            error = str(exception)
+
+        meth("%s. %s for %s at pos %s: %s",
+             message_base, error_desc, action_type, step + 1, error)
+
     async def _handle_action(self, action, variables, context):
         """Handle an action."""
         await self._actions[_determine_action(action)](

homeassistant/helpers/service.py

@@ -55,9 +55,13 @@ async def async_call_from_config(hass, config, blocking=False, variables=None,
                 variables)
             domain_service = cv.service(domain_service)
         except TemplateError as ex:
+            if blocking:
+                raise
             _LOGGER.error('Error rendering service name template: %s', ex)
             return
         except vol.Invalid:
+            if blocking:
+                raise
             _LOGGER.error('Template rendered invalid service: %s',
                           domain_service)
             return

tests/components/automation/test_init.py

@@ -864,3 +864,24 @@ def test_automation_not_trigger_on_bootstrap(hass):
 
     assert len(calls) == 1
     assert ['hello.world'] == calls[0].data.get(ATTR_ENTITY_ID)
+
+
+async def test_automation_with_error_in_script(hass, caplog):
+    """Test automation with an error in script."""
+    assert await async_setup_component(hass, automation.DOMAIN, {
+        automation.DOMAIN: {
+            'alias': 'hello',
+            'trigger': {
+                'platform': 'event',
+                'event_type': 'test_event',
+            },
+            'action': {
+                'service': 'test.automation',
+                'entity_id': 'hello.world'
+            }
+        }
+    })
+
+    hass.bus.async_fire('test_event')
+    await hass.async_block_till_done()
+    assert 'Service test.automation not found' in caplog.text

tests/helpers/test_script.py

@@ -4,6 +4,7 @@ from datetime import timedelta
 from unittest import mock
 import unittest
 
+import jinja2
 import voluptuous as vol
 import pytest
 
@@ -798,6 +799,7 @@ async def test_propagate_error_service_not_found(hass):
         await script_obj.async_run()
 
     assert len(events) == 0
+    assert script_obj._cur == -1
 
 
 async def test_propagate_error_invalid_service_data(hass):
@@ -829,6 +831,7 @@ async def test_propagate_error_invalid_service_data(hass):
 
     assert len(events) == 0
     assert len(calls) == 0
+    assert script_obj._cur == -1
 
 
 async def test_propagate_error_service_exception(hass):
@@ -859,3 +862,35 @@ async def test_propagate_error_service_exception(hass):
 
     assert len(events) == 0
     assert len(calls) == 0
+    assert script_obj._cur == -1
+
+
+def test_log_exception():
+    """Test logged output."""
+    script_obj = script.Script(None, cv.SCRIPT_SCHEMA([
+        {'service': 'test.script'},
+        {'event': 'test_event'}]))
+    script_obj._exception_step = 1
+
+    for exc, msg in (
+        (vol.Invalid("Invalid number"), 'Invalid data'),
+        (exceptions.TemplateError(jinja2.TemplateError('Unclosed bracket')),
+         'Error rendering template'),
+        (exceptions.Unauthorized(), 'Unauthorized'),
+        (exceptions.ServiceNotFound('light', 'turn_on'), 'Service not found'),
+        (ValueError("Cannot parse JSON"), 'Unknown error'),
+    ):
+        logger = mock.Mock()
+        script_obj.async_log_exception(logger, 'Test error', exc)
+
+        assert len(logger.mock_calls) == 1
+        p_format, p_msg_base, p_error_desc, p_action_type, p_step, p_error = \
+            logger.mock_calls[0][1]
+
+        assert p_error_desc == msg
+        assert p_action_type == script.ACTION_FIRE_EVENT
+        assert p_step == 2
+        if isinstance(exc, ValueError):
+            assert p_error == ""
+        else:
+            assert p_error == str(exc)