diff --git a/homeassistant/helpers/entity_component.py b/homeassistant/helpers/entity_component.py index 26c633820cf..908685205e7 100644 --- a/homeassistant/helpers/entity_component.py +++ b/homeassistant/helpers/entity_component.py @@ -18,6 +18,7 @@ from homeassistant.util.async import ( run_callback_threadsafe, run_coroutine_threadsafe) DEFAULT_SCAN_INTERVAL = timedelta(seconds=15) +SLOW_SETUP_WARNING = 10 class EntityComponent(object): @@ -134,8 +135,13 @@ class EntityComponent(object): self, platform_type, scan_interval, entity_namespace) entity_platform = self._platforms[key] + self.logger.info("Setting up %s.%s", self.domain, platform_type) + warn_task = self.hass.loop.call_later( + SLOW_SETUP_WARNING, self.logger.warning, + 'Setup of platform %s is taking over %s seconds.', platform_type, + SLOW_SETUP_WARNING) + try: - self.logger.info("Setting up %s.%s", self.domain, platform_type) if getattr(platform, 'async_setup_platform', None): yield from platform.async_setup_platform( self.hass, platform_config, @@ -154,6 +160,8 @@ class EntityComponent(object): except Exception: # pylint: disable=broad-except self.logger.exception( 'Error while setting up platform %s', platform_type) + finally: + warn_task.cancel() def add_entity(self, entity, platform=None, update_before_add=False): """Add entity to component.""" diff --git a/homeassistant/setup.py b/homeassistant/setup.py index b9652787eff..4a4737dab03 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -21,6 +21,8 @@ ATTR_COMPONENT = 'component' DATA_SETUP = 'setup_tasks' DATA_PIP_LOCK = 'pip_lock' +SLOW_SETUP_WARNING = 10 + def setup_component(hass: core.HomeAssistant, domain: str, config: Optional[Dict]=None) -> bool: @@ -172,8 +174,12 @@ def _async_setup_component(hass: core.HomeAssistant, async_comp = hasattr(component, 'async_setup') + _LOGGER.info("Setting up %s", domain) + warn_task = hass.loop.call_later( + SLOW_SETUP_WARNING, _LOGGER.warning, + 'Setup of %s is taking over %s seconds.', domain, SLOW_SETUP_WARNING) + try: - _LOGGER.info("Setting up %s", domain) if async_comp: result = yield from component.async_setup(hass, processed_config) else: @@ -183,6 +189,8 @@ def _async_setup_component(hass: core.HomeAssistant, _LOGGER.exception('Error during setup of component %s', domain) async_notify_setup_error(hass, domain, True) return False + finally: + warn_task.cancel() if result is False: log_error('Component failed to initialize.') diff --git a/tests/helpers/test_entity_component.py b/tests/helpers/test_entity_component.py index 395ef103fd3..3af01140c4d 100644 --- a/tests/helpers/test_entity_component.py +++ b/tests/helpers/test_entity_component.py @@ -4,7 +4,7 @@ import asyncio from collections import OrderedDict import logging import unittest -from unittest.mock import patch, Mock +from unittest.mock import patch, Mock, MagicMock from datetime import timedelta import homeassistant.core as ha @@ -12,7 +12,7 @@ import homeassistant.loader as loader from homeassistant.components import group from homeassistant.helpers.entity import Entity, generate_entity_id from homeassistant.helpers.entity_component import ( - EntityComponent, DEFAULT_SCAN_INTERVAL) + EntityComponent, DEFAULT_SCAN_INTERVAL, SLOW_SETUP_WARNING) from homeassistant.helpers import discovery import homeassistant.util.dt as dt_util @@ -410,3 +410,30 @@ class TestHelpersEntityComponent(unittest.TestCase): return entity component.add_entities(create_entity(i) for i in range(2)) + + +@asyncio.coroutine +def test_platform_warn_slow_setup(hass): + """Warn we log when platform setup takes a long time.""" + platform = MockPlatform() + + loader.set_component('test_domain.platform', platform) + + component = EntityComponent(_LOGGER, DOMAIN, hass) + + with patch.object(hass.loop, 'call_later', MagicMock()) \ + as mock_call: + yield from component.async_setup({ + DOMAIN: { + 'platform': 'platform', + } + }) + assert mock_call.called + assert len(mock_call.mock_calls) == 2 + + timeout, logger_method = mock_call.mock_calls[0][1][:2] + + assert timeout == SLOW_SETUP_WARNING + assert logger_method == _LOGGER.warning + + assert mock_call().cancel.called diff --git a/tests/test_setup.py b/tests/test_setup.py index f14561a0c48..9d29961da10 100644 --- a/tests/test_setup.py +++ b/tests/test_setup.py @@ -407,3 +407,23 @@ def test_component_cannot_depend_config(hass): result = yield from setup._async_process_dependencies( hass, None, 'test', ['config']) assert not result + + +@asyncio.coroutine +def test_component_warn_slow_setup(hass): + """Warn we log when a component setup takes a long time.""" + loader.set_component('test_component1', MockModule('test_component1')) + with mock.patch.object(hass.loop, 'call_later', mock.MagicMock()) \ + as mock_call: + result = yield from setup.async_setup_component( + hass, 'test_component1', {}) + assert result + assert mock_call.called + assert len(mock_call.mock_calls) == 2 + + timeout, logger_method = mock_call.mock_calls[0][1][:2] + + assert timeout == setup.SLOW_SETUP_WARNING + assert logger_method == setup._LOGGER.warning + + assert mock_call().cancel.called