From da84b0782256cdb81abfa44cbc8a080b14064be9 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 22 Mar 2021 16:00:39 -1000 Subject: [PATCH 01/30] dispatch every second --- homeassistant/bootstrap.py | 22 ++++++++-- .../components/websocket_api/commands.py | 40 +++++++++++++++++++ tests/test_bootstrap.py | 4 +- 3 files changed, 61 insertions(+), 5 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index d19ddaf4f5d6e1..dd8757d44d2ada 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -20,6 +20,7 @@ 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, @@ -28,6 +29,7 @@ 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 +44,8 @@ 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 +384,29 @@ def _get_domains(hass: core.HomeAssistant, config: dict[str, Any]) -> set[str]: return domains -async def _async_log_pending_setups( +async def _async_watch_pending_setups( hass: core.HomeAssistant, domains: set[str], setup_started: dict[str, datetime] ) -> None: """Periodic log of setups that are pending for longer than LOG_SLOW_STARTUP_INTERVAL.""" + loop_count = 0 while True: - await asyncio.sleep(LOG_SLOW_STARTUP_INTERVAL) + now = dt_util.utcnow() remaining = [domain for domain in domains if domain in setup_started] + remaining_with_setup_started = { + domain: (now - setup_started[domain]).seconds for domain in remaining + } + 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 remaining: _LOGGER.warning( "Waiting on integrations to complete setup: %s", ", ".join(remaining), ) + loop_count = 0 _LOGGER.debug("Running timeout Zones: %s", hass.timeout.zones) @@ -408,7 +422,7 @@ async def async_setup_multi_components( for domain in domains } log_task = asyncio.create_task( - _async_log_pending_setups(hass, domains, setup_started) + _async_watch_pending_setups(hass, domains, setup_started) ) await asyncio.wait(futures.values()) log_task.cancel() diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index 2912512fa62bf2..e38516637da5b2 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -4,6 +4,7 @@ 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,6 +15,7 @@ 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 @@ -37,10 +39,12 @@ def async_register_commands(hass, async_reg): 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) async_reg(hass, handle_unsubscribe_events) + async_reg(hass, handle_unsubscribe_bootstrap_integrations) def pong_message(iden): @@ -95,6 +99,42 @@ def forward_events(event): 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( + { + vol.Required("type"): "unsubscribe_bootstrap_integrations", + vol.Required("subscription"): cv.positive_int, + } +) +def handle_unsubscribe_bootstrap_integrations(hass, connection, msg): + """Handle unsubscribe bootstrap integrations command.""" + # Currently these are the same as events so we pass on the request + # This api call only exists in case we change the implementation + # details. + return handle_unsubscribe_events(hass, connection, msg) + + @callback @decorators.websocket_command( { diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index c035f6f1d1d791..24646386278974 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -431,7 +431,9 @@ async def _async_setup_that_blocks_startup(*args, **kwargs): 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, ): From e2fc9dd7f9f60801af01de6b2179ec375ea93550 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 22 Mar 2021 16:01:56 -1000 Subject: [PATCH 02/30] debug --- homeassistant/bootstrap.py | 1 + 1 file changed, 1 insertion(+) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index dd8757d44d2ada..9023dbb27bca53 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -395,6 +395,7 @@ async def _async_watch_pending_setups( remaining_with_setup_started = { domain: (now - setup_started[domain]).seconds for domain in remaining } + _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) async_dispatcher_send( hass, SIGNAL_BOOTSTRAP_INTEGRATONS, remaining_with_setup_started ) From c1f47bdc417b9152dfc0d1ceb94a87515b797b7d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:06:49 -1000 Subject: [PATCH 03/30] Make setup time a context manager --- homeassistant/components/notify/__init__.py | 77 ++++----- homeassistant/helpers/entity_platform.py | 139 +++++++++-------- homeassistant/setup.py | 163 +++++++++++--------- 3 files changed, 203 insertions(+), 176 deletions(-) diff --git a/homeassistant/components/notify/__init__.py b/homeassistant/components/notify/__init__.py index e64ceb48a217ae..118579fb0c0c7b 100644 --- a/homeassistant/components/notify/__init__.py +++ b/homeassistant/components/notify/__init__.py @@ -16,7 +16,7 @@ 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_platform( _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/helpers/entity_platform.py b/homeassistant/helpers/entity_platform.py index 00783b072c9a25..80186fd28a36fc 100644 --- a/homeassistant/helpers/entity_platform.py +++ b/homeassistant/helpers/entity_platform.py @@ -4,6 +4,7 @@ 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 @@ 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 @@ 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 @@ async def _async_setup_platform( self.platform_name, SLOW_SETUP_WARNING, ) - - try: - task = async_create_setup_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() - - 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", + with async_start_setup(hass, [full_name]): + try: + task = async_create_setup_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() + + 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, + ) + + 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 @@ -643,6 +647,7 @@ async def _update_entity_states(self, now: datetime) -> None: for entity in self.entities.values(): if not entity.should_poll: continue + _LOGGER.debug("Entity: %s is using polling", entity.entity_id) tasks.append(entity.async_update_ha_state(True)) if tasks: diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 6b306995dfc28e..e0fd72960339c1 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -2,10 +2,11 @@ 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 @@ -42,6 +43,8 @@ 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,78 @@ def log_error(msg: str, link: str | None = 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 - 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, - ) + 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 + 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.") + 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, + ) + 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, - ) - 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) + # 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) - ] - ) + 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 +417,23 @@ 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.""" + hass.data.setdefault(DATA_SETUP_STARTED, {}) + + started = dt_util.utcnow() + for domain in components: + hass.data[DATA_SETUP_STARTED][domain] = started + + yield + + if domain in hass.data[DATA_SETUP_STARTED]: + del hass.data[DATA_SETUP_STARTED][domain] + + hass.data.setdefault(DATA_SETUP_TIME, {}) + time_taken = dt_util.utcnow() - started + for domain in components: + hass.data[DATA_SETUP_TIME][domain] = time_taken From c3fa70943cc729cd0c0510b1f80869076f1d0c53 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:17:45 -1000 Subject: [PATCH 04/30] fix --- homeassistant/bootstrap.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 9023dbb27bca53..9739929b6a3048 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -402,7 +402,7 @@ async def _async_watch_pending_setups( await asyncio.sleep(SLOW_STARTUP_CHECK_INTERVAL) loop_count += SLOW_STARTUP_CHECK_INTERVAL - if loop_count > LOG_SLOW_STARTUP_INTERVAL and remaining: + if loop_count >= LOG_SLOW_STARTUP_INTERVAL and remaining: _LOGGER.warning( "Waiting on integrations to complete setup: %s", ", ".join(remaining), From 599b6c92b75a3cff71a478ea41a9c57877ea8816 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:25:16 -1000 Subject: [PATCH 05/30] handle multiple ping sensors --- homeassistant/setup.py | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index e0fd72960339c1..e7a8828e5586f8 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -13,7 +13,7 @@ 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__) @@ -425,15 +425,16 @@ def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generat hass.data.setdefault(DATA_SETUP_STARTED, {}) started = dt_util.utcnow() + unique_components = [] for domain in components: - hass.data[DATA_SETUP_STARTED][domain] = started + unique = ensure_unique_string(domain, hass.data[DATA_SETUP_STARTED]) + unique_components.append(unique) + hass.data[DATA_SETUP_STARTED][unique] = started yield - if domain in hass.data[DATA_SETUP_STARTED]: - del hass.data[DATA_SETUP_STARTED][domain] - hass.data.setdefault(DATA_SETUP_TIME, {}) time_taken = dt_util.utcnow() - started - for domain in components: + for domain in unique_components: + del hass.data[DATA_SETUP_STARTED][domain] hass.data[DATA_SETUP_TIME][domain] = time_taken From 0ef0de3f9e0106f01ea99e8cb061e46077a86f04 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:31:01 -1000 Subject: [PATCH 06/30] reduce --- homeassistant/bootstrap.py | 31 +++++++++++++------------------ homeassistant/setup.py | 3 --- 2 files changed, 13 insertions(+), 21 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 9739929b6a3048..87a02a8766199b 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -25,6 +25,7 @@ from homeassistant.setup import ( DATA_SETUP, DATA_SETUP_STARTED, + DATA_SETUP_TIME, async_set_domains_to_be_loaded, async_setup_component, ) @@ -384,16 +385,15 @@ def _get_domains(hass: core.HomeAssistant, config: dict[str, Any]) -> set[str]: return domains -async def _async_watch_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: now = dt_util.utcnow() - remaining = [domain for domain in domains if domain in setup_started] + remaining = setup_started.keys() remaining_with_setup_started = { - domain: (now - setup_started[domain]).seconds for domain in remaining + domain: (now - setup_started[domain]).seconds for domain in setup_started } _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) async_dispatcher_send( @@ -415,16 +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_watch_pending_setups(hass, domains, setup_started) - ) + log_task = asyncio.create_task(_async_watch_pending_setups(hass)) await asyncio.wait(futures.values()) log_task.cancel() errors = [domain for domain in domains if futures[domain].exception()] @@ -442,7 +439,9 @@ 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] = {} + hass.data[DATA_SETUP_TIME] = {} + domains_to_setup = _get_domains(hass, config) # Resolve all dependencies so we know all integrations @@ -491,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() @@ -539,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") @@ -554,9 +551,7 @@ 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") diff --git a/homeassistant/setup.py b/homeassistant/setup.py index e7a8828e5586f8..1e4ab7445f4788 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -422,8 +422,6 @@ def async_get_loaded_integrations(hass: core.HomeAssistant) -> set: @contextlib.contextmanager def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generator: """Keep track of when setup starts and finishes.""" - hass.data.setdefault(DATA_SETUP_STARTED, {}) - started = dt_util.utcnow() unique_components = [] for domain in components: @@ -433,7 +431,6 @@ def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generat yield - hass.data.setdefault(DATA_SETUP_TIME, {}) time_taken = dt_util.utcnow() - started for domain in unique_components: del hass.data[DATA_SETUP_STARTED][domain] From 6473bfcff3b5d50812732ab65b6b888e7b234e28 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:35:24 -1000 Subject: [PATCH 07/30] fix --- homeassistant/setup.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 1e4ab7445f4788..196341b5a49981 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -422,6 +422,7 @@ def async_get_loaded_integrations(hass: core.HomeAssistant) -> set: @contextlib.contextmanager def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generator: """Keep track of when setup starts and finishes.""" + hass.data.setdefault(DATA_SETUP_STARTED, {}) started = dt_util.utcnow() unique_components = [] for domain in components: @@ -431,6 +432,7 @@ def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generat yield + hass.data.setdefault(DATA_SETUP_TIME, {}) time_taken = dt_util.utcnow() - started for domain in unique_components: del hass.data[DATA_SETUP_STARTED][domain] From 516d769bd2fef8b040a88b21f11b9ca110855e8d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:48:59 -1000 Subject: [PATCH 08/30] add to the right place --- homeassistant/setup.py | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index 196341b5a49981..b7b615a911c512 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -424,16 +424,20 @@ def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generat """Keep track of when setup starts and finishes.""" hass.data.setdefault(DATA_SETUP_STARTED, {}) started = dt_util.utcnow() - unique_components = [] + unique_components = {} for domain in components: unique = ensure_unique_string(domain, hass.data[DATA_SETUP_STARTED]) - unique_components.append(unique) + unique_components[unique] = domain hass.data[DATA_SETUP_STARTED][unique] = started yield hass.data.setdefault(DATA_SETUP_TIME, {}) time_taken = dt_util.utcnow() - started - for domain in unique_components: - del hass.data[DATA_SETUP_STARTED][domain] - hass.data[DATA_SETUP_TIME][domain] = time_taken + for unique, domain in unique_components.items(): + del hass.data[DATA_SETUP_STARTED][unique] + if "." in domain: + _, integration = domain.split(".", 1) + hass.data[DATA_SETUP_TIME][integration] += time_taken + else: + hass.data[DATA_SETUP_TIME][domain] += time_taken From 92fc5d649b68b6cea303c8d0c7b30c6a71263f05 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:50:55 -1000 Subject: [PATCH 09/30] add to the right place --- homeassistant/setup.py | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index b7b615a911c512..b91addeb07db13 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -422,22 +422,25 @@ def async_get_loaded_integrations(hass: core.HomeAssistant) -> set: @contextlib.contextmanager def async_start_setup(hass: core.HomeAssistant, components: Iterable) -> Generator: """Keep track of when setup starts and finishes.""" - hass.data.setdefault(DATA_SETUP_STARTED, {}) + setup_started = hass.data.setdefault(DATA_SETUP_STARTED, {}) started = dt_util.utcnow() unique_components = {} for domain in components: - unique = ensure_unique_string(domain, hass.data[DATA_SETUP_STARTED]) + unique = ensure_unique_string(domain, setup_started) unique_components[unique] = domain - hass.data[DATA_SETUP_STARTED][unique] = started + setup_started[unique] = started yield - hass.data.setdefault(DATA_SETUP_TIME, {}) + setup_time = hass.data.setdefault(DATA_SETUP_TIME, {}) time_taken = dt_util.utcnow() - started for unique, domain in unique_components.items(): - del hass.data[DATA_SETUP_STARTED][unique] + del setup_started[unique] if "." in domain: _, integration = domain.split(".", 1) - hass.data[DATA_SETUP_TIME][integration] += time_taken else: - hass.data[DATA_SETUP_TIME][domain] += time_taken + integration = domain + if integration in setup_time: + setup_time[integration] += time_taken + else: + setup_time[integration] = time_taken From 326e455e02fc059e1645ab5ee3ee9363578d13eb Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 24 Mar 2021 09:55:58 -1000 Subject: [PATCH 10/30] log --- homeassistant/bootstrap.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 87a02a8766199b..581d740bb6c826 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -440,7 +440,7 @@ async def _async_set_up_integrations( ) -> None: """Set up all the integrations.""" hass.data[DATA_SETUP_STARTED] = {} - hass.data[DATA_SETUP_TIME] = {} + setup_time = hass.data[DATA_SETUP_TIME] = {} domains_to_setup = _get_domains(hass, config) @@ -562,3 +562,5 @@ async def _async_set_up_integrations( await hass.async_block_till_done() except asyncio.TimeoutError: _LOGGER.warning("Setup timed out for bootstrap - moving forward") + + _LOGGER.debug("Setup times: %s", setup_time) From 69b0c1f92af3cf5d3713fb609f70895add5d812a Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 08:05:16 -1000 Subject: [PATCH 11/30] merge --- .../components/device_tracker/legacy.py | 90 ++++++++++--------- 1 file changed, 48 insertions(+), 42 deletions(-) diff --git a/homeassistant/components/device_tracker/legacy.py b/homeassistant/components/device_tracker/legacy.py index eae133965c6d9e..cd9b7034aa2f53 100644 --- a/homeassistant/components/device_tracker/legacy.py +++ b/homeassistant/components/device_tracker/legacy.py @@ -38,7 +38,7 @@ ) 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 @@ def type(self): 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.") - - if setup: - hass.config.components.add(f"{DOMAIN}.{self.name}") - - if scanner: - async_setup_scanner_platform( - hass, self.config, scanner, tracker.async_see, self.type + 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 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): From f96077c948bf6b837d37cac879705f6535eda0f4 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 08:30:20 -1000 Subject: [PATCH 12/30] add api --- .../components/websocket_api/commands.py | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index e38516637da5b2..06e05546bdd2e9 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -19,7 +19,7 @@ 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 @@ -36,6 +36,7 @@ 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) async_reg(hass, handle_manifest_list) async_reg(hass, handle_ping) async_reg(hass, handle_render_template) @@ -278,6 +279,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"}) +@decorators.async_response +async def handle_integration_setup(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): From 1ff8f3f9d613b29e6721b742a65e979d84de4518 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 16:13:41 -1000 Subject: [PATCH 13/30] adjust --- homeassistant/bootstrap.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 581d740bb6c826..775b5655be4d7a 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -421,9 +421,7 @@ async def async_setup_multi_components( domain: hass.async_create_task(async_setup_component(hass, domain, config)) for domain in domains } - log_task = asyncio.create_task(_async_watch_pending_setups(hass)) 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() @@ -442,6 +440,8 @@ async def _async_set_up_integrations( 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 @@ -564,3 +564,4 @@ async def _async_set_up_integrations( _LOGGER.warning("Setup timed out for bootstrap - moving forward") _LOGGER.debug("Setup times: %s", setup_time) + log_task.cancel() From c576e20ef0693796ad65f769eca3f20a70eab523 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 16:16:55 -1000 Subject: [PATCH 14/30] adjust --- homeassistant/bootstrap.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 775b5655be4d7a..3ae3945915dc88 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -555,6 +555,9 @@ async def _async_set_up_integrations( except asyncio.TimeoutError: _LOGGER.warning("Setup timed out for stage 2 - moving forward") + log_task.cancel() + _LOGGER.debug("Setup times: %s", setup_time) + # Wrap up startup _LOGGER.debug("Waiting for startup to wrap up") try: @@ -562,6 +565,3 @@ async def _async_set_up_integrations( await hass.async_block_till_done() except asyncio.TimeoutError: _LOGGER.warning("Setup timed out for bootstrap - moving forward") - - _LOGGER.debug("Setup times: %s", setup_time) - log_task.cancel() From 990bdc1e106c48f6c20b61dc6144867dc25526de Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 16:21:51 -1000 Subject: [PATCH 15/30] adjust --- homeassistant/bootstrap.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 3ae3945915dc88..b200019c0907a2 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -556,7 +556,13 @@ async def _async_set_up_integrations( _LOGGER.warning("Setup timed out for stage 2 - moving forward") log_task.cancel() - _LOGGER.debug("Setup times: %s", setup_time) + _LOGGER.info( + "Integration setup times: %s", + { + integration: timedelta.total_seconds() + for integration, timedelta in setup_time + }, + ) # Wrap up startup _LOGGER.debug("Waiting for startup to wrap up") From 10b196d169155f8484f1be136b27cd569cbe7dbd Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 16:46:53 -1000 Subject: [PATCH 16/30] fix --- homeassistant/bootstrap.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index b200019c0907a2..d18b93656071e6 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -560,7 +560,7 @@ async def _async_set_up_integrations( "Integration setup times: %s", { integration: timedelta.total_seconds() - for integration, timedelta in setup_time + for integration, timedelta in setup_time.items() }, ) From fd3c6713728d960668a5deaa722e0c236221cc9b Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 25 Mar 2021 21:30:46 -1000 Subject: [PATCH 17/30] sort --- homeassistant/bootstrap.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index d18b93656071e6..a542b0debb211b 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -560,7 +560,9 @@ async def _async_set_up_integrations( "Integration setup times: %s", { integration: timedelta.total_seconds() - for integration, timedelta in setup_time.items() + for integration, timedelta in sorted( + setup_time.items(), key=lambda item: item[1].total_seconds() # type: ignore + ) }, ) From 1f23ae482a07a51acf94f4295bd6e1caf36ff06c Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 28 Mar 2021 13:58:14 -1000 Subject: [PATCH 18/30] coverage --- homeassistant/bootstrap.py | 3 +- .../components/websocket_api/test_commands.py | 55 ++++++++++++++++++- 2 files changed, 56 insertions(+), 2 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index a542b0debb211b..db048329a3692b 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -393,7 +393,8 @@ async def _async_watch_pending_setups(hass: core.HomeAssistant) -> None: now = dt_util.utcnow() remaining = setup_started.keys() remaining_with_setup_started = { - domain: (now - setup_started[domain]).seconds for domain in 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( diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index da42e175ff360a..260a508dd96c9a 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.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,53 @@ 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 + + await websocket_client.send_json( + {"id": 8, "type": "unsubscribe_bootstrap_integrations", "subscription": 7} + ) + msg = await websocket_client.receive_json() + assert msg["id"] == 8 + assert msg["success"] is True + assert msg["type"] == "result" + assert msg["result"] is None + + +async def test_integration_setup(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"}) + + 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}, + ] From 0396044125001461b3b0b79056ff495af40d93bc Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 28 Mar 2021 14:07:52 -1000 Subject: [PATCH 19/30] coverage --- tests/test_setup.py | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/tests/test_setup.py b/tests/test_setup.py index 9b68dbf4eab5da..72613722ca1f1f 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] From de4da02e4481992ef969dc1c46cee436040bbe3d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 29 Mar 2021 12:06:39 -1000 Subject: [PATCH 20/30] fix merge --- homeassistant/components/device_tracker/legacy.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/components/device_tracker/legacy.py b/homeassistant/components/device_tracker/legacy.py index cd9b7034aa2f53..a90d92944a4d82 100644 --- a/homeassistant/components/device_tracker/legacy.py +++ b/homeassistant/components/device_tracker/legacy.py @@ -251,7 +251,7 @@ async def async_setup_legacy(self, hass, tracker, discovery_info=None): raise HomeAssistantError("Invalid legacy device_tracker platform.") if setup: - hass.config.components.add(f"{DOMAIN}.{self.name}") + hass.config.components.add(full_name) if scanner: async_setup_scanner_platform( From 40a5476e5f008790ae34131b6717e8da6952924d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Mon, 29 Mar 2021 12:28:48 -1000 Subject: [PATCH 21/30] remove extra line from conflict resolution error --- homeassistant/setup.py | 1 - 1 file changed, 1 deletion(-) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index b91addeb07db13..c65e428e03a451 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -234,7 +234,6 @@ def log_error(msg: str, link: str | None = None) -> None: ) 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: From 12c99cf4a2d91042fd4a6fb577b809386fd41f87 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 30 Mar 2021 11:34:52 -1000 Subject: [PATCH 22/30] Update homeassistant/bootstrap.py --- homeassistant/bootstrap.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index db048329a3692b..732bef03358167 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -557,7 +557,7 @@ async def _async_set_up_integrations( _LOGGER.warning("Setup timed out for stage 2 - moving forward") log_task.cancel() - _LOGGER.info( + _LOGGER.debug( "Integration setup times: %s", { integration: timedelta.total_seconds() From 5998872380a34310e0da7549cd0afed2cff07f84 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 10:27:00 -1000 Subject: [PATCH 23/30] remove debug --- homeassistant/helpers/entity_platform.py | 1 - 1 file changed, 1 deletion(-) diff --git a/homeassistant/helpers/entity_platform.py b/homeassistant/helpers/entity_platform.py index 80186fd28a36fc..dc7386c18a8cb4 100644 --- a/homeassistant/helpers/entity_platform.py +++ b/homeassistant/helpers/entity_platform.py @@ -647,7 +647,6 @@ async def _update_entity_states(self, now: datetime) -> None: for entity in self.entities.values(): if not entity.should_poll: continue - _LOGGER.debug("Entity: %s is using polling", entity.entity_id) tasks.append(entity.async_update_ha_state(True)) if tasks: From e3c2bbe9125e07f0c837369c0a557935e2fa4321 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 12:12:16 -1000 Subject: [PATCH 24/30] Update homeassistant/components/websocket_api/commands.py --- homeassistant/components/websocket_api/commands.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index 06e05546bdd2e9..acd2761335e1b1 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -133,7 +133,7 @@ def handle_unsubscribe_bootstrap_integrations(hass, connection, msg): # Currently these are the same as events so we pass on the request # This api call only exists in case we change the implementation # details. - return handle_unsubscribe_events(hass, connection, msg) + handle_unsubscribe_events(hass, connection, msg) @callback From 3634b17a9cfd004158c52003d8e3698306319f76 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 21:14:35 -1000 Subject: [PATCH 25/30] Update homeassistant/components/websocket_api/commands.py Co-authored-by: Paulus Schoutsen --- homeassistant/components/websocket_api/commands.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index acd2761335e1b1..9b4529e3faa1b6 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -279,7 +279,7 @@ 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"}) +@decorators.websocket_command({vol.Required("type"): "integration/setup_info"}) @decorators.async_response async def handle_integration_setup(hass, connection, msg): """Handle integrations command.""" From 54139ed19ed3ba59805a408a2bcd301be40a65d8 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 21:15:51 -1000 Subject: [PATCH 26/30] remove handle_unsubscribe_bootstrap_integrations --- .../components/websocket_api/commands.py | 16 ---------------- tests/components/websocket_api/test_commands.py | 9 --------- 2 files changed, 25 deletions(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index 9b4529e3faa1b6..a0dbc5d189c4f5 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -45,7 +45,6 @@ def async_register_commands(hass, async_reg): async_reg(hass, handle_subscribe_trigger) async_reg(hass, handle_test_condition) async_reg(hass, handle_unsubscribe_events) - async_reg(hass, handle_unsubscribe_bootstrap_integrations) def pong_message(iden): @@ -121,21 +120,6 @@ def forward_bootstrap_integrations(message): connection.send_message(messages.result_message(msg["id"])) -@callback -@decorators.websocket_command( - { - vol.Required("type"): "unsubscribe_bootstrap_integrations", - vol.Required("subscription"): cv.positive_int, - } -) -def handle_unsubscribe_bootstrap_integrations(hass, connection, msg): - """Handle unsubscribe bootstrap integrations command.""" - # Currently these are the same as events so we pass on the request - # This api call only exists in case we change the implementation - # details. - handle_unsubscribe_events(hass, connection, msg) - - @callback @decorators.websocket_command( { diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index 260a508dd96c9a..3cd0566088791b 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -1151,15 +1151,6 @@ async def test_subscribe_unsubscribe_bootstrap_integrations( assert msg["type"] == "result" assert msg["result"] == message - await websocket_client.send_json( - {"id": 8, "type": "unsubscribe_bootstrap_integrations", "subscription": 7} - ) - msg = await websocket_client.receive_json() - assert msg["id"] == 8 - assert msg["success"] is True - assert msg["type"] == "result" - assert msg["result"] is None - async def test_integration_setup(hass, websocket_client, hass_admin_user): """Test subscribe/unsubscribe bootstrap_integrations.""" From 952d6979bebb8edff3f3a8f2896714b5abccac54 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 21:19:30 -1000 Subject: [PATCH 27/30] drop remaining --- homeassistant/bootstrap.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 732bef03358167..b43e789005b5e6 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -391,7 +391,6 @@ async def _async_watch_pending_setups(hass: core.HomeAssistant) -> None: setup_started: dict[str, datetime] = hass.data[DATA_SETUP_STARTED] while True: now = dt_util.utcnow() - remaining = setup_started.keys() remaining_with_setup_started = { domain: (now - setup_started[domain]).total_seconds() for domain in setup_started @@ -403,10 +402,10 @@ async def _async_watch_pending_setups(hass: core.HomeAssistant) -> None: await asyncio.sleep(SLOW_STARTUP_CHECK_INTERVAL) loop_count += SLOW_STARTUP_CHECK_INTERVAL - if loop_count >= LOG_SLOW_STARTUP_INTERVAL and 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) From 13b721eb50bb039c1f2fbec71610284b64ddee7f Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 21:23:03 -1000 Subject: [PATCH 28/30] adjust test to match change in name --- tests/components/websocket_api/test_commands.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/components/websocket_api/test_commands.py b/tests/components/websocket_api/test_commands.py index 3cd0566088791b..09123db4579974 100644 --- a/tests/components/websocket_api/test_commands.py +++ b/tests/components/websocket_api/test_commands.py @@ -1152,13 +1152,13 @@ async def test_subscribe_unsubscribe_bootstrap_integrations( assert msg["result"] == message -async def test_integration_setup(hass, websocket_client, hass_admin_user): +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"}) + await websocket_client.send_json({"id": 7, "type": "integration/setup_info"}) msg = await websocket_client.receive_json() assert msg["id"] == 7 From da811ba9b54874ebf380b798cb3eae3dc35422a0 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 21:23:58 -1000 Subject: [PATCH 29/30] Update homeassistant/components/websocket_api/commands.py --- homeassistant/components/websocket_api/commands.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index a0dbc5d189c4f5..c858ba79848888 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -36,7 +36,7 @@ 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) + async_reg(hass, handle_integration_setup_info) async_reg(hass, handle_manifest_list) async_reg(hass, handle_ping) async_reg(hass, handle_render_template) From f00aa02d359d9c32c26bff95301bd6fc2eb16705 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 4 Apr 2021 21:24:08 -1000 Subject: [PATCH 30/30] Update homeassistant/components/websocket_api/commands.py --- homeassistant/components/websocket_api/commands.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/homeassistant/components/websocket_api/commands.py b/homeassistant/components/websocket_api/commands.py index c858ba79848888..f7961046043a66 100644 --- a/homeassistant/components/websocket_api/commands.py +++ b/homeassistant/components/websocket_api/commands.py @@ -265,7 +265,7 @@ async def handle_manifest_get(hass, connection, msg): @decorators.websocket_command({vol.Required("type"): "integration/setup_info"}) @decorators.async_response -async def handle_integration_setup(hass, connection, msg): +async def handle_integration_setup_info(hass, connection, msg): """Handle integrations command.""" connection.send_result( msg["id"],