diff --git a/homeassistant/components/automation/__init__.py b/homeassistant/components/automation/__init__.py index d062376f2a8..6c9b04f9fa2 100644 --- a/homeassistant/components/automation/__init__.py +++ b/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) - await script_obj.async_run(variables, context) + 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 diff --git a/homeassistant/helpers/script.py b/homeassistant/helpers/script.py index 088882df608..e4693c3cd3b 100644 --- a/homeassistant/helpers/script.py +++ b/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)]( diff --git a/homeassistant/helpers/service.py b/homeassistant/helpers/service.py index f51d0f8b248..66488fbec3d 100644 --- a/homeassistant/helpers/service.py +++ b/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 diff --git a/tests/components/automation/test_init.py b/tests/components/automation/test_init.py index a01b48b9190..12c97507a13 100644 --- a/tests/components/automation/test_init.py +++ b/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 diff --git a/tests/helpers/test_script.py b/tests/helpers/test_script.py index 887a147c417..d04044d9b60 100644 --- a/tests/helpers/test_script.py +++ b/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)