diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index d19ddaf4f5d..b43e789005b 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -20,14 +20,17 @@ from homeassistant.components import http from homeassistant.const import REQUIRED_NEXT_PYTHON_DATE, REQUIRED_NEXT_PYTHON_VER from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers import area_registry, device_registry, entity_registry +from homeassistant.helpers.dispatcher import async_dispatcher_send from homeassistant.helpers.typing import ConfigType from homeassistant.setup import ( DATA_SETUP, DATA_SETUP_STARTED, + DATA_SETUP_TIME, async_set_domains_to_be_loaded, async_setup_component, ) from homeassistant.util.async_ import gather_with_concurrency +import homeassistant.util.dt as dt_util from homeassistant.util.logging import async_activate_log_queue_handler from homeassistant.util.package import async_get_user_site, is_virtual_env @@ -42,6 +45,8 @@ ERROR_LOG_FILENAME = "home-assistant.log" DATA_LOGGING = "logging" LOG_SLOW_STARTUP_INTERVAL = 60 +SLOW_STARTUP_CHECK_INTERVAL = 1 +SIGNAL_BOOTSTRAP_INTEGRATONS = "bootstrap_integrations" STAGE_1_TIMEOUT = 120 STAGE_2_TIMEOUT = 300 @@ -380,19 +385,29 @@ def _get_domains(hass: core.HomeAssistant, config: dict[str, Any]) -> set[str]: return domains -async def _async_log_pending_setups( - hass: core.HomeAssistant, domains: set[str], setup_started: dict[str, datetime] -) -> None: +async def _async_watch_pending_setups(hass: core.HomeAssistant) -> None: """Periodic log of setups that are pending for longer than LOG_SLOW_STARTUP_INTERVAL.""" + loop_count = 0 + setup_started: dict[str, datetime] = hass.data[DATA_SETUP_STARTED] while True: - await asyncio.sleep(LOG_SLOW_STARTUP_INTERVAL) - remaining = [domain for domain in domains if domain in setup_started] + now = dt_util.utcnow() + remaining_with_setup_started = { + domain: (now - setup_started[domain]).total_seconds() + for domain in setup_started + } + _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) + async_dispatcher_send( + hass, SIGNAL_BOOTSTRAP_INTEGRATONS, remaining_with_setup_started + ) + await asyncio.sleep(SLOW_STARTUP_CHECK_INTERVAL) + loop_count += SLOW_STARTUP_CHECK_INTERVAL - if remaining: + if loop_count >= LOG_SLOW_STARTUP_INTERVAL and setup_started: _LOGGER.warning( "Waiting on integrations to complete setup: %s", - ", ".join(remaining), + ", ".join(setup_started), ) + loop_count = 0 _LOGGER.debug("Running timeout Zones: %s", hass.timeout.zones) @@ -400,18 +415,13 @@ async def async_setup_multi_components( hass: core.HomeAssistant, domains: set[str], config: dict[str, Any], - setup_started: dict[str, datetime], ) -> None: """Set up multiple domains. Log on failure.""" futures = { domain: hass.async_create_task(async_setup_component(hass, domain, config)) for domain in domains } - log_task = asyncio.create_task( - _async_log_pending_setups(hass, domains, setup_started) - ) 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() @@ -427,7 +437,11 @@ async def _async_set_up_integrations( hass: core.HomeAssistant, config: dict[str, Any] ) -> None: """Set up all the integrations.""" - setup_started = hass.data[DATA_SETUP_STARTED] = {} + hass.data[DATA_SETUP_STARTED] = {} + setup_time = hass.data[DATA_SETUP_TIME] = {} + + log_task = asyncio.create_task(_async_watch_pending_setups(hass)) + domains_to_setup = _get_domains(hass, config) # Resolve all dependencies so we know all integrations @@ -476,14 +490,14 @@ async def _async_set_up_integrations( # Load logging as soon as possible if logging_domains: _LOGGER.info("Setting up logging: %s", logging_domains) - await async_setup_multi_components(hass, logging_domains, config, setup_started) + await async_setup_multi_components(hass, logging_domains, config) # Start up debuggers. Start these first in case they want to wait. debuggers = domains_to_setup & DEBUGGER_INTEGRATIONS if debuggers: _LOGGER.debug("Setting up debuggers: %s", debuggers) - await async_setup_multi_components(hass, debuggers, config, setup_started) + await async_setup_multi_components(hass, debuggers, config) # calculate what components to setup in what stage stage_1_domains = set() @@ -524,9 +538,7 @@ async def _async_set_up_integrations( async with hass.timeout.async_timeout( STAGE_1_TIMEOUT, cool_down=COOLDOWN_TIME ): - await async_setup_multi_components( - hass, stage_1_domains, config, setup_started - ) + await async_setup_multi_components(hass, stage_1_domains, config) except asyncio.TimeoutError: _LOGGER.warning("Setup timed out for stage 1 - moving forward") @@ -539,12 +551,21 @@ async def _async_set_up_integrations( async with hass.timeout.async_timeout( STAGE_2_TIMEOUT, cool_down=COOLDOWN_TIME ): - await async_setup_multi_components( - hass, stage_2_domains, config, setup_started - ) + await async_setup_multi_components(hass, stage_2_domains, config) except asyncio.TimeoutError: _LOGGER.warning("Setup timed out for stage 2 - moving forward") + log_task.cancel() + _LOGGER.debug( + "Integration setup times: %s", + { + integration: timedelta.total_seconds() + for integration, timedelta in sorted( + setup_time.items(), key=lambda item: item[1].total_seconds() # type: ignore + ) + }, + ) + # Wrap up startup _LOGGER.debug("Waiting for startup to wrap up") try: diff --git a/homeassistant/components/device_tracker/legacy.py b/homeassistant/components/device_tracker/legacy.py index eae133965c6..a90d92944a4 100644 --- a/homeassistant/components/device_tracker/legacy.py +++ b/homeassistant/components/device_tracker/legacy.py @@ -38,7 +38,7 @@ from homeassistant.helpers.event import ( ) from homeassistant.helpers.restore_state import RestoreEntity from homeassistant.helpers.typing import ConfigType, GPSType -from homeassistant.setup import async_prepare_setup_platform +from homeassistant.setup import async_prepare_setup_platform, async_start_setup from homeassistant.util import dt as dt_util from homeassistant.util.yaml import dump @@ -221,48 +221,54 @@ class DeviceTrackerPlatform: async def async_setup_legacy(self, hass, tracker, discovery_info=None): """Set up a legacy platform.""" - LOGGER.info("Setting up %s.%s", DOMAIN, self.name) - try: - scanner = None - setup = None - if hasattr(self.platform, "async_get_scanner"): - scanner = await self.platform.async_get_scanner( - hass, {DOMAIN: self.config} - ) - elif hasattr(self.platform, "get_scanner"): - scanner = await hass.async_add_executor_job( - self.platform.get_scanner, hass, {DOMAIN: self.config} - ) - elif hasattr(self.platform, "async_setup_scanner"): - setup = await self.platform.async_setup_scanner( - hass, self.config, tracker.async_see, discovery_info - ) - elif hasattr(self.platform, "setup_scanner"): - setup = await hass.async_add_executor_job( - self.platform.setup_scanner, - hass, - self.config, - tracker.see, - discovery_info, - ) - else: - raise HomeAssistantError("Invalid legacy device_tracker platform.") + full_name = f"{DOMAIN}.{self.name}" + LOGGER.info("Setting up %s", full_name) + with async_start_setup(hass, [full_name]): + try: + scanner = None + setup = None + if hasattr(self.platform, "async_get_scanner"): + scanner = await self.platform.async_get_scanner( + hass, {DOMAIN: self.config} + ) + elif hasattr(self.platform, "get_scanner"): + scanner = await hass.async_add_executor_job( + self.platform.get_scanner, hass, {DOMAIN: self.config} + ) + elif hasattr(self.platform, "async_setup_scanner"): + setup = await self.platform.async_setup_scanner( + hass, self.config, tracker.async_see, discovery_info + ) + elif hasattr(self.platform, "setup_scanner"): + setup = await hass.async_add_executor_job( + self.platform.setup_scanner, + hass, + self.config, + tracker.see, + discovery_info, + ) + else: + raise HomeAssistantError("Invalid legacy device_tracker platform.") - if setup: - hass.config.components.add(f"{DOMAIN}.{self.name}") + if setup: + hass.config.components.add(full_name) - if scanner: - async_setup_scanner_platform( - hass, self.config, scanner, tracker.async_see, self.type + if scanner: + async_setup_scanner_platform( + hass, self.config, scanner, tracker.async_see, self.type + ) + return + + if not setup: + LOGGER.error( + "Error setting up platform %s %s", self.type, self.name + ) + return + + except Exception: # pylint: disable=broad-except + LOGGER.exception( + "Error setting up platform %s %s", self.type, self.name ) - return - - if not setup: - LOGGER.error("Error setting up platform %s %s", self.type, self.name) - return - - except Exception: # pylint: disable=broad-except - LOGGER.exception("Error setting up platform %s %s", self.type, self.name) async def async_extract_config(hass, config): diff --git a/homeassistant/components/notify/__init__.py b/homeassistant/components/notify/__init__.py index e64ceb48a21..118579fb0c0 100644 --- a/homeassistant/components/notify/__init__.py +++ b/homeassistant/components/notify/__init__.py @@ -16,7 +16,7 @@ from homeassistant.helpers import config_per_platform, discovery import homeassistant.helpers.config_validation as cv from homeassistant.helpers.service import async_set_service_schema from homeassistant.loader import async_get_integration, bind_hass -from homeassistant.setup import async_prepare_setup_platform +from homeassistant.setup import async_prepare_setup_platform, async_start_setup from homeassistant.util import slugify from homeassistant.util.yaml import load_yaml @@ -289,47 +289,52 @@ async def async_setup(hass, config): _LOGGER.error("Unknown notification service specified") return - _LOGGER.info("Setting up %s.%s", DOMAIN, integration_name) - notify_service = None - try: - if hasattr(platform, "async_get_service"): - notify_service = await platform.async_get_service( - hass, p_config, discovery_info - ) - elif hasattr(platform, "get_service"): - notify_service = await hass.async_add_executor_job( - platform.get_service, hass, p_config, discovery_info - ) - else: - raise HomeAssistantError("Invalid notify platform.") - - if notify_service is None: - # Platforms can decide not to create a service based - # on discovery data. - if discovery_info is None: - _LOGGER.error( - "Failed to initialize notification service %s", integration_name + full_name = f"{DOMAIN}.{integration_name}" + _LOGGER.info("Setting up %s", full_name) + with async_start_setup(hass, [full_name]): + notify_service = None + try: + if hasattr(platform, "async_get_service"): + notify_service = await platform.async_get_service( + hass, p_config, discovery_info ) + elif hasattr(platform, "get_service"): + notify_service = await hass.async_add_executor_job( + platform.get_service, hass, p_config, discovery_info + ) + else: + raise HomeAssistantError("Invalid notify platform.") + + if notify_service is None: + # Platforms can decide not to create a service based + # on discovery data. + if discovery_info is None: + _LOGGER.error( + "Failed to initialize notification service %s", + integration_name, + ) + return + + except Exception: # pylint: disable=broad-except + _LOGGER.exception("Error setting up platform %s", integration_name) return - except Exception: # pylint: disable=broad-except - _LOGGER.exception("Error setting up platform %s", integration_name) - return + if discovery_info is None: + discovery_info = {} - if discovery_info is None: - discovery_info = {} + conf_name = p_config.get(CONF_NAME) or discovery_info.get(CONF_NAME) + target_service_name_prefix = conf_name or integration_name + service_name = slugify(conf_name or SERVICE_NOTIFY) - conf_name = p_config.get(CONF_NAME) or discovery_info.get(CONF_NAME) - target_service_name_prefix = conf_name or integration_name - service_name = slugify(conf_name or SERVICE_NOTIFY) + await notify_service.async_setup( + hass, service_name, target_service_name_prefix + ) + await notify_service.async_register_services() - await notify_service.async_setup(hass, service_name, target_service_name_prefix) - await notify_service.async_register_services() - - hass.data[NOTIFY_SERVICES].setdefault(integration_name, []).append( - notify_service - ) - hass.config.components.add(f"{DOMAIN}.{integration_name}") + hass.data[NOTIFY_SERVICES].setdefault(integration_name, []).append( + notify_service + ) + hass.config.components.add(f"{DOMAIN}.{integration_name}") return True diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index 2912512fa62..f7961046043 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -4,6 +4,7 @@ import asyncio import voluptuous as vol from homeassistant.auth.permissions.const import CAT_ENTITIES, POLICY_READ +from homeassistant.bootstrap import SIGNAL_BOOTSTRAP_INTEGRATONS from homeassistant.components.websocket_api.const import ERR_NOT_FOUND from homeassistant.const import EVENT_STATE_CHANGED, EVENT_TIME_CHANGED, MATCH_ALL from homeassistant.core import DOMAIN as HASS_DOMAIN, callback @@ -14,10 +15,11 @@ from homeassistant.exceptions import ( Unauthorized, ) from homeassistant.helpers import config_validation as cv, entity, template +from homeassistant.helpers.dispatcher import async_dispatcher_connect from homeassistant.helpers.event import TrackTemplate, async_track_template_result from homeassistant.helpers.service import async_get_all_descriptions from homeassistant.loader import IntegrationNotFound, async_get_integration -from homeassistant.setup import async_get_loaded_integrations +from homeassistant.setup import DATA_SETUP_TIME, async_get_loaded_integrations from . import const, decorators, messages @@ -34,9 +36,11 @@ def async_register_commands(hass, async_reg): async_reg(hass, handle_get_services) async_reg(hass, handle_get_states) async_reg(hass, handle_manifest_get) + async_reg(hass, handle_integration_setup_info) async_reg(hass, handle_manifest_list) async_reg(hass, handle_ping) async_reg(hass, handle_render_template) + async_reg(hass, handle_subscribe_bootstrap_integrations) async_reg(hass, handle_subscribe_events) async_reg(hass, handle_subscribe_trigger) async_reg(hass, handle_test_condition) @@ -95,6 +99,27 @@ def handle_subscribe_events(hass, connection, msg): connection.send_message(messages.result_message(msg["id"])) +@callback +@decorators.websocket_command( + { + vol.Required("type"): "subscribe_bootstrap_integrations", + } +) +def handle_subscribe_bootstrap_integrations(hass, connection, msg): + """Handle subscribe bootstrap integrations command.""" + + @callback + def forward_bootstrap_integrations(message): + """Forward bootstrap integrations to websocket.""" + connection.send_message(messages.result_message(msg["id"], message)) + + connection.subscriptions[msg["id"]] = async_dispatcher_connect( + hass, SIGNAL_BOOTSTRAP_INTEGRATONS, forward_bootstrap_integrations + ) + + connection.send_message(messages.result_message(msg["id"])) + + @callback @decorators.websocket_command( { @@ -238,6 +263,19 @@ async def handle_manifest_get(hass, connection, msg): connection.send_error(msg["id"], const.ERR_NOT_FOUND, "Integration not found") +@decorators.websocket_command({vol.Required("type"): "integration/setup_info"}) +@decorators.async_response +async def handle_integration_setup_info(hass, connection, msg): + """Handle integrations command.""" + connection.send_result( + msg["id"], + [ + {"domain": integration, "seconds": timedelta.total_seconds()} + for integration, timedelta in hass.data[DATA_SETUP_TIME].items() + ], + ) + + @callback @decorators.websocket_command({vol.Required("type"): "ping"}) def handle_ping(hass, connection, msg): diff --git a/homeassistant/helpers/entity_platform.py b/homeassistant/helpers/entity_platform.py index 00783b072c9..dc7386c18a8 100644 --- a/homeassistant/helpers/entity_platform.py +++ b/homeassistant/helpers/entity_platform.py @@ -4,6 +4,7 @@ from __future__ import annotations import asyncio from contextvars import ContextVar from datetime import datetime, timedelta +import logging from logging import Logger from types import ModuleType from typing import TYPE_CHECKING, Callable, Coroutine, Iterable @@ -30,6 +31,7 @@ from homeassistant.helpers import ( entity_registry as ent_reg, service, ) +from homeassistant.setup import async_start_setup from homeassistant.util.async_ import run_callback_threadsafe from .entity_registry import DISABLED_INTEGRATION @@ -48,6 +50,8 @@ PLATFORM_NOT_READY_RETRIES = 10 DATA_ENTITY_PLATFORM = "entity_platform" PLATFORM_NOT_READY_BASE_WAIT_TIME = 30 # seconds +_LOGGER = logging.getLogger(__name__) + class EntityPlatform: """Manage the entities for a single platform.""" @@ -202,77 +206,77 @@ class EntityPlatform: self.platform_name, SLOW_SETUP_WARNING, ) + with async_start_setup(hass, [full_name]): + try: + task = async_create_setup_task() - try: - task = async_create_setup_task() + async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, self.domain): + await asyncio.shield(task) - async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, self.domain): - await asyncio.shield(task) + # Block till all entities are done + while self._tasks: + pending = [task for task in self._tasks if not task.done()] + self._tasks.clear() - # Block till all entities are done - while self._tasks: - pending = [task for task in self._tasks if not task.done()] - self._tasks.clear() + if pending: + await asyncio.gather(*pending) - if pending: - await asyncio.gather(*pending) + hass.config.components.add(full_name) + self._setup_complete = True + return True + except PlatformNotReady as ex: + tries += 1 + wait_time = min(tries, 6) * PLATFORM_NOT_READY_BASE_WAIT_TIME + message = str(ex) + if not message and ex.__cause__: + message = str(ex.__cause__) + ready_message = f"ready yet: {message}" if message else "ready yet" + if tries == 1: + logger.warning( + "Platform %s not %s; Retrying in background in %d seconds", + self.platform_name, + ready_message, + wait_time, + ) + else: + logger.debug( + "Platform %s not %s; Retrying in %d seconds", + self.platform_name, + ready_message, + wait_time, + ) - hass.config.components.add(full_name) - self._setup_complete = True - return True - except PlatformNotReady as ex: - tries += 1 - wait_time = min(tries, 6) * PLATFORM_NOT_READY_BASE_WAIT_TIME - message = str(ex) - if not message and ex.__cause__: - message = str(ex.__cause__) - ready_message = f"ready yet: {message}" if message else "ready yet" - if tries == 1: - logger.warning( - "Platform %s not %s; Retrying in background in %d seconds", + async def setup_again(*_): # type: ignore[no-untyped-def] + """Run setup again.""" + self._async_cancel_retry_setup = None + await self._async_setup_platform(async_create_setup_task, tries) + + if hass.state == CoreState.running: + self._async_cancel_retry_setup = async_call_later( + hass, wait_time, setup_again + ) + else: + self._async_cancel_retry_setup = hass.bus.async_listen_once( + EVENT_HOMEASSISTANT_STARTED, setup_again + ) + return False + except asyncio.TimeoutError: + logger.error( + "Setup of platform %s is taking longer than %s seconds." + " Startup will proceed without waiting any longer.", self.platform_name, - ready_message, - wait_time, + SLOW_SETUP_MAX_WAIT, ) - else: - logger.debug( - "Platform %s not %s; Retrying in %d seconds", + return False + except Exception: # pylint: disable=broad-except + logger.exception( + "Error while setting up %s platform for %s", self.platform_name, - ready_message, - wait_time, + self.domain, ) - - async def setup_again(*_): # type: ignore[no-untyped-def] - """Run setup again.""" - self._async_cancel_retry_setup = None - await self._async_setup_platform(async_create_setup_task, tries) - - if hass.state == CoreState.running: - self._async_cancel_retry_setup = async_call_later( - hass, wait_time, setup_again - ) - else: - self._async_cancel_retry_setup = hass.bus.async_listen_once( - EVENT_HOMEASSISTANT_STARTED, setup_again - ) - return False - except asyncio.TimeoutError: - logger.error( - "Setup of platform %s is taking longer than %s seconds." - " Startup will proceed without waiting any longer.", - self.platform_name, - SLOW_SETUP_MAX_WAIT, - ) - return False - except Exception: # pylint: disable=broad-except - logger.exception( - "Error while setting up %s platform for %s", - self.platform_name, - self.domain, - ) - return False - finally: - warn_task.cancel() + return False + finally: + warn_task.cancel() def _schedule_add_entities( self, new_entities: Iterable[Entity], update_before_add: bool = False diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 6b306995dfc..c65e428e03a 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -2,17 +2,18 @@ from __future__ import annotations import asyncio +import contextlib import logging.handlers from timeit import default_timer as timer from types import ModuleType -from typing import Awaitable, Callable +from typing import Awaitable, Callable, Generator, Iterable from homeassistant import config as conf_util, core, loader, requirements from homeassistant.config import async_notify_setup_error 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 +from homeassistant.util import dt as dt_util, ensure_unique_string _LOGGER = logging.getLogger(__name__) @@ -42,6 +43,8 @@ BASE_PLATFORMS = { DATA_SETUP_DONE = "setup_done" DATA_SETUP_STARTED = "setup_started" +DATA_SETUP_TIME = "setup_time" + DATA_SETUP = "setup_tasks" DATA_DEPS_REQS = "deps_reqs_processed" @@ -205,84 +208,77 @@ async def _async_setup_component( 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 - warn_task = None - else: - warn_task = hass.loop.call_later( - SLOW_SETUP_WARNING, - _LOGGER.warning, - "Setup of %s is taking over %s seconds.", - domain, - SLOW_SETUP_WARNING, - ) - - task = None - result = True - try: - if hasattr(component, "async_setup"): - task = component.async_setup(hass, processed_config) # type: ignore - elif hasattr(component, "setup"): - # This should not be replaced with hass.async_add_executor_job because - # we don't want to track this task in case it blocks startup. - task = hass.loop.run_in_executor( - None, component.setup, hass, processed_config # type: ignore + with async_start_setup(hass, [domain]): + if hasattr(component, "PLATFORM_SCHEMA"): + # Entity components have their own warning + warn_task = None + else: + warn_task = hass.loop.call_later( + SLOW_SETUP_WARNING, + _LOGGER.warning, + "Setup of %s is taking over %s seconds.", + domain, + SLOW_SETUP_WARNING, + ) + + task = None + result = True + try: + if hasattr(component, "async_setup"): + task = component.async_setup(hass, processed_config) # type: ignore + elif hasattr(component, "setup"): + # This should not be replaced with hass.async_add_executor_job because + # we don't want to track this task in case it blocks startup. + task = hass.loop.run_in_executor( + None, component.setup, hass, processed_config # type: ignore + ) + elif not hasattr(component, "async_setup_entry"): + log_error("No setup or config entry setup function defined.") + return False + + if task: + async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, domain): + result = await task + except asyncio.TimeoutError: + _LOGGER.error( + "Setup of %s is taking longer than %s seconds." + " Startup will proceed without waiting any longer", + domain, + SLOW_SETUP_MAX_WAIT, + ) + 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) + return False + finally: + end = timer() + if warn_task: + warn_task.cancel() + _LOGGER.info("Setup of domain %s took %.1f seconds", domain, end - start) + + if result is False: + log_error("Integration failed to initialize.") + return False + if result is not True: + log_error( + f"Integration {domain!r} did not return boolean if setup was " + "successful. Disabling component." ) - elif not hasattr(component, "async_setup_entry"): - log_error("No setup or config entry setup function defined.") - hass.data[DATA_SETUP_STARTED].pop(domain) return False - if task: - async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, domain): - result = await task - except asyncio.TimeoutError: - _LOGGER.error( - "Setup of %s is taking longer than %s seconds." - " Startup will proceed without waiting any longer", - domain, - SLOW_SETUP_MAX_WAIT, + # Flush out async_setup calling create_task. Fragile but covered by test. + await asyncio.sleep(0) + await hass.config_entries.flow.async_wait_init_flow_finish(domain) + + await asyncio.gather( + *[ + entry.async_setup(hass, integration=integration) + for entry in hass.config_entries.async_entries(domain) + ] ) - 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() - if warn_task: - warn_task.cancel() - _LOGGER.info("Setup of domain %s took %.1f seconds", domain, end - start) - 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. - await asyncio.sleep(0) - await hass.config_entries.flow.async_wait_init_flow_finish(domain) - - await asyncio.gather( - *[ - entry.async_setup(hass, integration=integration) - for entry in hass.config_entries.async_entries(domain) - ] - ) - - hass.config.components.add(domain) - hass.data[DATA_SETUP_STARTED].pop(domain) + hass.config.components.add(domain) # Cleanup if domain in hass.data[DATA_SETUP]: @@ -420,3 +416,30 @@ def async_get_loaded_integrations(hass: core.HomeAssistant) -> set: if domain in BASE_PLATFORMS: integrations.add(platform) return integrations + + +@contextlib.contextmanager +def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generator: + """Keep track of when setup starts and finishes.""" + setup_started = hass.data.setdefault(DATA_SETUP_STARTED, {}) + started = dt_util.utcnow() + unique_components = {} + for domain in components: + unique = ensure_unique_string(domain, setup_started) + unique_components[unique] = domain + setup_started[unique] = started + + yield + + setup_time = hass.data.setdefault(DATA_SETUP_TIME, {}) + time_taken = dt_util.utcnow() - started + for unique, domain in unique_components.items(): + del setup_started[unique] + if "." in domain: + _, integration = domain.split(".", 1) + else: + integration = domain + if integration in setup_time: + setup_time[integration] += time_taken + else: + setup_time[integration] = time_taken diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index da42e175ff3..09123db4579 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -1,10 +1,12 @@ """Tests for WebSocket API commands.""" +import datetime from unittest.mock import ANY, patch from async_timeout import timeout import pytest import voluptuous as vol +from homeassistant.bootstrap import SIGNAL_BOOTSTRAP_INTEGRATONS from homeassistant.components.websocket_api import const from homeassistant.components.websocket_api.auth import ( TYPE_AUTH, @@ -15,9 +17,10 @@ from homeassistant.components.websocket_api.const import URL from homeassistant.core import Context, callback from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers import entity +from homeassistant.helpers.dispatcher import async_dispatcher_send from homeassistant.helpers.typing import HomeAssistantType from homeassistant.loader import async_get_integration -from homeassistant.setup import async_setup_component +from homeassistant.setup import DATA_SETUP_TIME, async_setup_component from tests.common import MockEntity, MockEntityPlatform, async_mock_service @@ -1124,3 +1127,44 @@ async def test_execute_script(hass, websocket_client): assert call.service == "test_service" assert call.data == {"hello": "From variable"} assert call.context.as_dict() == msg_var["result"]["context"] + + +async def test_subscribe_unsubscribe_bootstrap_integrations( + hass, websocket_client, hass_admin_user +): + """Test subscribe/unsubscribe bootstrap_integrations.""" + await websocket_client.send_json( + {"id": 7, "type": "subscribe_bootstrap_integrations"} + ) + + msg = await websocket_client.receive_json() + assert msg["id"] == 7 + assert msg["type"] == const.TYPE_RESULT + assert msg["success"] + + message = {"august": 12.5, "isy994": 12.8} + + async_dispatcher_send(hass, SIGNAL_BOOTSTRAP_INTEGRATONS, message) + msg = await websocket_client.receive_json() + assert msg["id"] == 7 + assert msg["success"] is True + assert msg["type"] == "result" + assert msg["result"] == message + + +async def test_integration_setup_info(hass, websocket_client, hass_admin_user): + """Test subscribe/unsubscribe bootstrap_integrations.""" + hass.data[DATA_SETUP_TIME] = { + "august": datetime.timedelta(seconds=12.5), + "isy994": datetime.timedelta(seconds=12.8), + } + await websocket_client.send_json({"id": 7, "type": "integration/setup_info"}) + + msg = await websocket_client.receive_json() + assert msg["id"] == 7 + assert msg["type"] == const.TYPE_RESULT + assert msg["success"] + assert msg["result"] == [ + {"domain": "august", "seconds": 12.5}, + {"domain": "isy994", "seconds": 12.8}, + ] diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index c035f6f1d1d..24646386278 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -431,7 +431,9 @@ async def test_setup_hass_takes_longer_than_log_slow_startup( with patch( "homeassistant.config.async_hass_config_yaml", return_value={"browser": {}, "frontend": {}}, - ), patch.object(bootstrap, "LOG_SLOW_STARTUP_INTERVAL", 0.3), patch( + ), patch.object(bootstrap, "LOG_SLOW_STARTUP_INTERVAL", 0.3), patch.object( + bootstrap, "SLOW_STARTUP_CHECK_INTERVAL", 0.05 + ), patch( "homeassistant.components.frontend.async_setup", side_effect=_async_setup_that_blocks_startup, ): diff --git a/tests/test_setup.py b/tests/test_setup.py index 9b68dbf4eab..72613722ca1 100644 --- a/tests/test_setup.py +++ b/tests/test_setup.py @@ -1,6 +1,7 @@ """Test component/platform setup.""" # pylint: disable=protected-access import asyncio +import datetime import os import threading from unittest.mock import AsyncMock, Mock, patch @@ -644,3 +645,31 @@ async def test_integration_only_setup_entry(hass): ), ) assert await setup.async_setup_component(hass, "test_integration_only_entry", {}) + + +async def test_async_start_setup(hass): + """Test setup started context manager keeps track of setup times.""" + with setup.async_start_setup(hass, ["august"]): + assert isinstance( + hass.data[setup.DATA_SETUP_STARTED]["august"], datetime.datetime + ) + with setup.async_start_setup(hass, ["august"]): + assert isinstance( + hass.data[setup.DATA_SETUP_STARTED]["august_2"], datetime.datetime + ) + + assert "august" not in hass.data[setup.DATA_SETUP_STARTED] + assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], datetime.timedelta) + assert "august_2" not in hass.data[setup.DATA_SETUP_TIME] + + +async def test_async_start_setup_platforms(hass): + """Test setup started context manager keeps track of setup times for platforms.""" + with setup.async_start_setup(hass, ["sensor.august"]): + assert isinstance( + hass.data[setup.DATA_SETUP_STARTED]["sensor.august"], datetime.datetime + ) + + assert "august" not in hass.data[setup.DATA_SETUP_STARTED] + assert isinstance(hass.data[setup.DATA_SETUP_TIME]["august"], datetime.timedelta) + assert "sensor" not in hass.data[setup.DATA_SETUP_TIME]