diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 32a7384c350f8..1a4a7de4c18db 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -20,7 +20,7 @@ ) from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers.typing import ConfigType -from homeassistant.setup import DATA_SETUP, async_setup_component +from homeassistant.setup import DATA_SETUP, DATA_SETUP_STARTED, async_setup_component from homeassistant.util.logging import async_activate_log_queue_handler from homeassistant.util.package import async_get_user_site, is_virtual_env from homeassistant.util.yaml import clear_secret_cache @@ -32,6 +32,8 @@ # hass.data key for logging information. DATA_LOGGING = "logging" +LOG_SLOW_STARTUP_INTERVAL = 60 + DEBUGGER_INTEGRATIONS = {"ptvsd"} CORE_INTEGRATIONS = ("homeassistant", "persistent_notification") LOGGING_INTEGRATIONS = {"logger", "system_log", "sentry"} @@ -323,13 +325,30 @@ async def _async_set_up_integrations( ) -> None: """Set up all the integrations.""" + setup_started = hass.data[DATA_SETUP_STARTED] = {} + async def async_setup_multi_components(domains: Set[str]) -> None: """Set up multiple domains. Log on failure.""" + + async def _async_log_pending_setups() -> None: + """Periodic log of setups that are pending for longer than LOG_SLOW_STARTUP_INTERVAL.""" + while True: + await asyncio.sleep(LOG_SLOW_STARTUP_INTERVAL) + remaining = [domain for domain in domains if domain in setup_started] + + if remaining: + _LOGGER.info( + "Waiting on integrations to complete setup: %s", + ", ".join(remaining), + ) + futures = { domain: hass.async_create_task(async_setup_component(hass, domain, config)) for domain in domains } + log_task = hass.loop.create_task(_async_log_pending_setups()) await asyncio.wait(futures.values()) + log_task.cancel() errors = [domain for domain in domains if futures[domain].exception()] for domain in errors: exception = futures[domain].exception() diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 9c20216d4ecc8..67d9200df61bb 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -10,11 +10,13 @@ from homeassistant.const import EVENT_COMPONENT_LOADED, PLATFORM_FORMAT from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers.typing import ConfigType +from homeassistant.util import dt as dt_util _LOGGER = logging.getLogger(__name__) ATTR_COMPONENT = "component" +DATA_SETUP_STARTED = "setup_started" DATA_SETUP = "setup_tasks" DATA_DEPS_REQS = "deps_reqs_processed" @@ -155,6 +157,7 @@ def log_error(msg: str, link: Optional[str] = None) -> None: start = timer() _LOGGER.info("Setting up %s", domain) + hass.data.setdefault(DATA_SETUP_STARTED, {})[domain] = dt_util.utcnow() if hasattr(component, "PLATFORM_SCHEMA"): # Entity components have their own warning @@ -181,6 +184,7 @@ def log_error(msg: str, link: Optional[str] = None) -> None: ) else: log_error("No setup function defined.") + hass.data[DATA_SETUP_STARTED].pop(domain) return False result = await asyncio.wait_for(task, SLOW_SETUP_MAX_WAIT) @@ -191,10 +195,12 @@ def log_error(msg: str, link: Optional[str] = None) -> None: domain, SLOW_SETUP_MAX_WAIT, ) + hass.data[DATA_SETUP_STARTED].pop(domain) return False except Exception: # pylint: disable=broad-except _LOGGER.exception("Error during setup of component %s", domain) async_notify_setup_error(hass, domain, integration.documentation) + hass.data[DATA_SETUP_STARTED].pop(domain) return False finally: end = timer() @@ -204,12 +210,14 @@ def log_error(msg: str, link: Optional[str] = None) -> None: if result is False: log_error("Integration failed to initialize.") + hass.data[DATA_SETUP_STARTED].pop(domain) return False if result is not True: log_error( f"Integration {domain!r} did not return boolean if setup was " "successful. Disabling component." ) + hass.data[DATA_SETUP_STARTED].pop(domain) return False # Flush out async_setup calling create_task. Fragile but covered by test. @@ -224,6 +232,7 @@ def log_error(msg: str, link: Optional[str] = None) -> None: ) hass.config.components.add(domain) + hass.data[DATA_SETUP_STARTED].pop(domain) # Cleanup if domain in hass.data[DATA_SETUP]: diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index fc535d7e3a5d4..9597dfa60b88c 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -1,5 +1,6 @@ """Test the bootstrapping.""" # pylint: disable=protected-access +import asyncio import logging import os from unittest.mock import Mock @@ -249,6 +250,7 @@ async def test_setup_hass( mock_mount_local_lib_path, mock_ensure_config_exists, mock_process_ha_config_upgrade, + caplog, ): """Test it works.""" verbose = Mock() @@ -259,7 +261,7 @@ async def test_setup_hass( with patch( "homeassistant.config.async_hass_config_yaml", return_value={"browser": {}, "frontend": {}}, - ): + ), patch.object(bootstrap, "LOG_SLOW_STARTUP_INTERVAL", 5000): hass = await bootstrap.async_setup_hass( config_dir=get_test_config_dir(), verbose=verbose, @@ -270,6 +272,8 @@ async def test_setup_hass( safe_mode=False, ) + assert "Waiting on integrations to complete setup" not in caplog.text + assert "browser" in hass.config.components assert "safe_mode" not in hass.config.components @@ -286,6 +290,44 @@ async def test_setup_hass( assert len(mock_process_ha_config_upgrade.mock_calls) == 1 +async def test_setup_hass_takes_longer_than_log_slow_startup( + mock_enable_logging, + mock_is_virtual_env, + mock_mount_local_lib_path, + mock_ensure_config_exists, + mock_process_ha_config_upgrade, + caplog, +): + """Test it works.""" + verbose = Mock() + log_rotate_days = Mock() + log_file = Mock() + log_no_color = Mock() + + async def _async_setup_that_blocks_startup(*args, **kwargs): + await asyncio.sleep(0.6) + return True + + with patch( + "homeassistant.config.async_hass_config_yaml", + return_value={"browser": {}, "frontend": {}}, + ), patch.object(bootstrap, "LOG_SLOW_STARTUP_INTERVAL", 0.3), patch( + "homeassistant.components.frontend.async_setup", + side_effect=_async_setup_that_blocks_startup, + ): + await bootstrap.async_setup_hass( + config_dir=get_test_config_dir(), + verbose=verbose, + log_rotate_days=log_rotate_days, + log_file=log_file, + log_no_color=log_no_color, + skip_pip=True, + safe_mode=False, + ) + + assert "Waiting on integrations to complete setup" in caplog.text + + async def test_setup_hass_invalid_yaml( mock_enable_logging, mock_is_virtual_env,