Provide api to see which integrations are being loaded (#48274)

Co-authored-by: Paulus Schoutsen <paulus@home-assistant.io>
This commit is contained in:
J. Nick Koston 2021-04-04 22:11:44 -10:00 committed by GitHub
parent e925fd2228
commit 12e3bc8101
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 409 additions and 237 deletions

View File

@ -20,14 +20,17 @@ from homeassistant.components import http
from homeassistant.const import REQUIRED_NEXT_PYTHON_DATE, REQUIRED_NEXT_PYTHON_VER from homeassistant.const import REQUIRED_NEXT_PYTHON_DATE, REQUIRED_NEXT_PYTHON_VER
from homeassistant.exceptions import HomeAssistantError from homeassistant.exceptions import HomeAssistantError
from homeassistant.helpers import area_registry, device_registry, entity_registry 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.helpers.typing import ConfigType
from homeassistant.setup import ( from homeassistant.setup import (
DATA_SETUP, DATA_SETUP,
DATA_SETUP_STARTED, DATA_SETUP_STARTED,
DATA_SETUP_TIME,
async_set_domains_to_be_loaded, async_set_domains_to_be_loaded,
async_setup_component, async_setup_component,
) )
from homeassistant.util.async_ import gather_with_concurrency 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.logging import async_activate_log_queue_handler
from homeassistant.util.package import async_get_user_site, is_virtual_env 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" DATA_LOGGING = "logging"
LOG_SLOW_STARTUP_INTERVAL = 60 LOG_SLOW_STARTUP_INTERVAL = 60
SLOW_STARTUP_CHECK_INTERVAL = 1
SIGNAL_BOOTSTRAP_INTEGRATONS = "bootstrap_integrations"
STAGE_1_TIMEOUT = 120 STAGE_1_TIMEOUT = 120
STAGE_2_TIMEOUT = 300 STAGE_2_TIMEOUT = 300
@ -380,19 +385,29 @@ def _get_domains(hass: core.HomeAssistant, config: dict[str, Any]) -> set[str]:
return domains return domains
async def _async_log_pending_setups( async def _async_watch_pending_setups(hass: core.HomeAssistant) -> None:
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.""" """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: 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]).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( _LOGGER.warning(
"Waiting on integrations to complete setup: %s", "Waiting on integrations to complete setup: %s",
", ".join(remaining), ", ".join(setup_started),
) )
loop_count = 0
_LOGGER.debug("Running timeout Zones: %s", hass.timeout.zones) _LOGGER.debug("Running timeout Zones: %s", hass.timeout.zones)
@ -400,18 +415,13 @@ async def async_setup_multi_components(
hass: core.HomeAssistant, hass: core.HomeAssistant,
domains: set[str], domains: set[str],
config: dict[str, Any], config: dict[str, Any],
setup_started: dict[str, datetime],
) -> None: ) -> None:
"""Set up multiple domains. Log on failure.""" """Set up multiple domains. Log on failure."""
futures = { futures = {
domain: hass.async_create_task(async_setup_component(hass, domain, config)) domain: hass.async_create_task(async_setup_component(hass, domain, config))
for domain in domains for domain in domains
} }
log_task = asyncio.create_task(
_async_log_pending_setups(hass, domains, setup_started)
)
await asyncio.wait(futures.values()) await asyncio.wait(futures.values())
log_task.cancel()
errors = [domain for domain in domains if futures[domain].exception()] errors = [domain for domain in domains if futures[domain].exception()]
for domain in errors: for domain in errors:
exception = futures[domain].exception() exception = futures[domain].exception()
@ -427,7 +437,11 @@ async def _async_set_up_integrations(
hass: core.HomeAssistant, config: dict[str, Any] hass: core.HomeAssistant, config: dict[str, Any]
) -> None: ) -> None:
"""Set up all the integrations.""" """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) domains_to_setup = _get_domains(hass, config)
# Resolve all dependencies so we know all integrations # Resolve all dependencies so we know all integrations
@ -476,14 +490,14 @@ async def _async_set_up_integrations(
# Load logging as soon as possible # Load logging as soon as possible
if logging_domains: if logging_domains:
_LOGGER.info("Setting up logging: %s", 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. # Start up debuggers. Start these first in case they want to wait.
debuggers = domains_to_setup & DEBUGGER_INTEGRATIONS debuggers = domains_to_setup & DEBUGGER_INTEGRATIONS
if debuggers: if debuggers:
_LOGGER.debug("Setting up debuggers: %s", 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 # calculate what components to setup in what stage
stage_1_domains = set() stage_1_domains = set()
@ -524,9 +538,7 @@ async def _async_set_up_integrations(
async with hass.timeout.async_timeout( async with hass.timeout.async_timeout(
STAGE_1_TIMEOUT, cool_down=COOLDOWN_TIME STAGE_1_TIMEOUT, cool_down=COOLDOWN_TIME
): ):
await async_setup_multi_components( await async_setup_multi_components(hass, stage_1_domains, config)
hass, stage_1_domains, config, setup_started
)
except asyncio.TimeoutError: except asyncio.TimeoutError:
_LOGGER.warning("Setup timed out for stage 1 - moving forward") _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( async with hass.timeout.async_timeout(
STAGE_2_TIMEOUT, cool_down=COOLDOWN_TIME STAGE_2_TIMEOUT, cool_down=COOLDOWN_TIME
): ):
await async_setup_multi_components( await async_setup_multi_components(hass, stage_2_domains, config)
hass, stage_2_domains, config, setup_started
)
except asyncio.TimeoutError: except asyncio.TimeoutError:
_LOGGER.warning("Setup timed out for stage 2 - moving forward") _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 # Wrap up startup
_LOGGER.debug("Waiting for startup to wrap up") _LOGGER.debug("Waiting for startup to wrap up")
try: try:

View File

@ -38,7 +38,7 @@ from homeassistant.helpers.event import (
) )
from homeassistant.helpers.restore_state import RestoreEntity from homeassistant.helpers.restore_state import RestoreEntity
from homeassistant.helpers.typing import ConfigType, GPSType 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 import dt as dt_util
from homeassistant.util.yaml import dump from homeassistant.util.yaml import dump
@ -221,48 +221,54 @@ class DeviceTrackerPlatform:
async def async_setup_legacy(self, hass, tracker, discovery_info=None): async def async_setup_legacy(self, hass, tracker, discovery_info=None):
"""Set up a legacy platform.""" """Set up a legacy platform."""
LOGGER.info("Setting up %s.%s", DOMAIN, self.name) full_name = f"{DOMAIN}.{self.name}"
try: LOGGER.info("Setting up %s", full_name)
scanner = None with async_start_setup(hass, [full_name]):
setup = None try:
if hasattr(self.platform, "async_get_scanner"): scanner = None
scanner = await self.platform.async_get_scanner( setup = None
hass, {DOMAIN: self.config} if hasattr(self.platform, "async_get_scanner"):
) scanner = await self.platform.async_get_scanner(
elif hasattr(self.platform, "get_scanner"): hass, {DOMAIN: self.config}
scanner = await hass.async_add_executor_job( )
self.platform.get_scanner, hass, {DOMAIN: self.config} elif hasattr(self.platform, "get_scanner"):
) scanner = await hass.async_add_executor_job(
elif hasattr(self.platform, "async_setup_scanner"): self.platform.get_scanner, hass, {DOMAIN: self.config}
setup = await self.platform.async_setup_scanner( )
hass, self.config, tracker.async_see, discovery_info elif hasattr(self.platform, "async_setup_scanner"):
) setup = await self.platform.async_setup_scanner(
elif hasattr(self.platform, "setup_scanner"): hass, self.config, tracker.async_see, discovery_info
setup = await hass.async_add_executor_job( )
self.platform.setup_scanner, elif hasattr(self.platform, "setup_scanner"):
hass, setup = await hass.async_add_executor_job(
self.config, self.platform.setup_scanner,
tracker.see, hass,
discovery_info, self.config,
) tracker.see,
else: discovery_info,
raise HomeAssistantError("Invalid legacy device_tracker platform.") )
else:
raise HomeAssistantError("Invalid legacy device_tracker platform.")
if setup: if setup:
hass.config.components.add(f"{DOMAIN}.{self.name}") hass.config.components.add(full_name)
if scanner: if scanner:
async_setup_scanner_platform( async_setup_scanner_platform(
hass, self.config, scanner, tracker.async_see, self.type 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): async def async_extract_config(hass, config):

View File

@ -16,7 +16,7 @@ from homeassistant.helpers import config_per_platform, discovery
import homeassistant.helpers.config_validation as cv import homeassistant.helpers.config_validation as cv
from homeassistant.helpers.service import async_set_service_schema from homeassistant.helpers.service import async_set_service_schema
from homeassistant.loader import async_get_integration, bind_hass 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 import slugify
from homeassistant.util.yaml import load_yaml from homeassistant.util.yaml import load_yaml
@ -289,47 +289,52 @@ async def async_setup(hass, config):
_LOGGER.error("Unknown notification service specified") _LOGGER.error("Unknown notification service specified")
return return
_LOGGER.info("Setting up %s.%s", DOMAIN, integration_name) full_name = f"{DOMAIN}.{integration_name}"
notify_service = None _LOGGER.info("Setting up %s", full_name)
try: with async_start_setup(hass, [full_name]):
if hasattr(platform, "async_get_service"): notify_service = None
notify_service = await platform.async_get_service( try:
hass, p_config, discovery_info if hasattr(platform, "async_get_service"):
) notify_service = await platform.async_get_service(
elif hasattr(platform, "get_service"): hass, p_config, discovery_info
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
) )
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 return
except Exception: # pylint: disable=broad-except if discovery_info is None:
_LOGGER.exception("Error setting up platform %s", integration_name) discovery_info = {}
return
if discovery_info is None: conf_name = p_config.get(CONF_NAME) or discovery_info.get(CONF_NAME)
discovery_info = {} 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) await notify_service.async_setup(
target_service_name_prefix = conf_name or integration_name hass, service_name, target_service_name_prefix
service_name = slugify(conf_name or SERVICE_NOTIFY) )
await notify_service.async_register_services()
await notify_service.async_setup(hass, service_name, target_service_name_prefix) hass.data[NOTIFY_SERVICES].setdefault(integration_name, []).append(
await notify_service.async_register_services() notify_service
)
hass.data[NOTIFY_SERVICES].setdefault(integration_name, []).append( hass.config.components.add(f"{DOMAIN}.{integration_name}")
notify_service
)
hass.config.components.add(f"{DOMAIN}.{integration_name}")
return True return True

View File

@ -4,6 +4,7 @@ import asyncio
import voluptuous as vol import voluptuous as vol
from homeassistant.auth.permissions.const import CAT_ENTITIES, POLICY_READ 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.components.websocket_api.const import ERR_NOT_FOUND
from homeassistant.const import EVENT_STATE_CHANGED, EVENT_TIME_CHANGED, MATCH_ALL from homeassistant.const import EVENT_STATE_CHANGED, EVENT_TIME_CHANGED, MATCH_ALL
from homeassistant.core import DOMAIN as HASS_DOMAIN, callback from homeassistant.core import DOMAIN as HASS_DOMAIN, callback
@ -14,10 +15,11 @@ from homeassistant.exceptions import (
Unauthorized, Unauthorized,
) )
from homeassistant.helpers import config_validation as cv, entity, template 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.event import TrackTemplate, async_track_template_result
from homeassistant.helpers.service import async_get_all_descriptions from homeassistant.helpers.service import async_get_all_descriptions
from homeassistant.loader import IntegrationNotFound, async_get_integration 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 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_services)
async_reg(hass, handle_get_states) async_reg(hass, handle_get_states)
async_reg(hass, handle_manifest_get) async_reg(hass, handle_manifest_get)
async_reg(hass, handle_integration_setup_info)
async_reg(hass, handle_manifest_list) async_reg(hass, handle_manifest_list)
async_reg(hass, handle_ping) async_reg(hass, handle_ping)
async_reg(hass, handle_render_template) async_reg(hass, handle_render_template)
async_reg(hass, handle_subscribe_bootstrap_integrations)
async_reg(hass, handle_subscribe_events) async_reg(hass, handle_subscribe_events)
async_reg(hass, handle_subscribe_trigger) async_reg(hass, handle_subscribe_trigger)
async_reg(hass, handle_test_condition) 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"])) 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 @callback
@decorators.websocket_command( @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") 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 @callback
@decorators.websocket_command({vol.Required("type"): "ping"}) @decorators.websocket_command({vol.Required("type"): "ping"})
def handle_ping(hass, connection, msg): def handle_ping(hass, connection, msg):

View File

@ -4,6 +4,7 @@ from __future__ import annotations
import asyncio import asyncio
from contextvars import ContextVar from contextvars import ContextVar
from datetime import datetime, timedelta from datetime import datetime, timedelta
import logging
from logging import Logger from logging import Logger
from types import ModuleType from types import ModuleType
from typing import TYPE_CHECKING, Callable, Coroutine, Iterable from typing import TYPE_CHECKING, Callable, Coroutine, Iterable
@ -30,6 +31,7 @@ from homeassistant.helpers import (
entity_registry as ent_reg, entity_registry as ent_reg,
service, service,
) )
from homeassistant.setup import async_start_setup
from homeassistant.util.async_ import run_callback_threadsafe from homeassistant.util.async_ import run_callback_threadsafe
from .entity_registry import DISABLED_INTEGRATION from .entity_registry import DISABLED_INTEGRATION
@ -48,6 +50,8 @@ PLATFORM_NOT_READY_RETRIES = 10
DATA_ENTITY_PLATFORM = "entity_platform" DATA_ENTITY_PLATFORM = "entity_platform"
PLATFORM_NOT_READY_BASE_WAIT_TIME = 30 # seconds PLATFORM_NOT_READY_BASE_WAIT_TIME = 30 # seconds
_LOGGER = logging.getLogger(__name__)
class EntityPlatform: class EntityPlatform:
"""Manage the entities for a single platform.""" """Manage the entities for a single platform."""
@ -202,77 +206,77 @@ class EntityPlatform:
self.platform_name, self.platform_name,
SLOW_SETUP_WARNING, SLOW_SETUP_WARNING,
) )
with async_start_setup(hass, [full_name]):
try:
task = async_create_setup_task()
try: async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, self.domain):
task = async_create_setup_task() await asyncio.shield(task)
async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, self.domain): # Block till all entities are done
await asyncio.shield(task) while self._tasks:
pending = [task for task in self._tasks if not task.done()]
self._tasks.clear()
# Block till all entities are done if pending:
while self._tasks: await asyncio.gather(*pending)
pending = [task for task in self._tasks if not task.done()]
self._tasks.clear()
if pending: hass.config.components.add(full_name)
await asyncio.gather(*pending) 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) async def setup_again(*_): # type: ignore[no-untyped-def]
self._setup_complete = True """Run setup again."""
return True self._async_cancel_retry_setup = None
except PlatformNotReady as ex: await self._async_setup_platform(async_create_setup_task, tries)
tries += 1
wait_time = min(tries, 6) * PLATFORM_NOT_READY_BASE_WAIT_TIME if hass.state == CoreState.running:
message = str(ex) self._async_cancel_retry_setup = async_call_later(
if not message and ex.__cause__: hass, wait_time, setup_again
message = str(ex.__cause__) )
ready_message = f"ready yet: {message}" if message else "ready yet" else:
if tries == 1: self._async_cancel_retry_setup = hass.bus.async_listen_once(
logger.warning( EVENT_HOMEASSISTANT_STARTED, setup_again
"Platform %s not %s; Retrying in background in %d seconds", )
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, self.platform_name,
ready_message, SLOW_SETUP_MAX_WAIT,
wait_time,
) )
else: return False
logger.debug( except Exception: # pylint: disable=broad-except
"Platform %s not %s; Retrying in %d seconds", logger.exception(
"Error while setting up %s platform for %s",
self.platform_name, self.platform_name,
ready_message, self.domain,
wait_time,
) )
return False
async def setup_again(*_): # type: ignore[no-untyped-def] finally:
"""Run setup again.""" warn_task.cancel()
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()
def _schedule_add_entities( def _schedule_add_entities(
self, new_entities: Iterable[Entity], update_before_add: bool = False self, new_entities: Iterable[Entity], update_before_add: bool = False

View File

@ -2,17 +2,18 @@
from __future__ import annotations from __future__ import annotations
import asyncio import asyncio
import contextlib
import logging.handlers import logging.handlers
from timeit import default_timer as timer from timeit import default_timer as timer
from types import ModuleType 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 import config as conf_util, core, loader, requirements
from homeassistant.config import async_notify_setup_error from homeassistant.config import async_notify_setup_error
from homeassistant.const import EVENT_COMPONENT_LOADED, PLATFORM_FORMAT from homeassistant.const import EVENT_COMPONENT_LOADED, PLATFORM_FORMAT
from homeassistant.exceptions import HomeAssistantError from homeassistant.exceptions import HomeAssistantError
from homeassistant.helpers.typing import ConfigType 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__) _LOGGER = logging.getLogger(__name__)
@ -42,6 +43,8 @@ BASE_PLATFORMS = {
DATA_SETUP_DONE = "setup_done" DATA_SETUP_DONE = "setup_done"
DATA_SETUP_STARTED = "setup_started" DATA_SETUP_STARTED = "setup_started"
DATA_SETUP_TIME = "setup_time"
DATA_SETUP = "setup_tasks" DATA_SETUP = "setup_tasks"
DATA_DEPS_REQS = "deps_reqs_processed" DATA_DEPS_REQS = "deps_reqs_processed"
@ -205,84 +208,77 @@ async def _async_setup_component(
start = timer() start = timer()
_LOGGER.info("Setting up %s", domain) _LOGGER.info("Setting up %s", domain)
hass.data.setdefault(DATA_SETUP_STARTED, {})[domain] = dt_util.utcnow() with async_start_setup(hass, [domain]):
if hasattr(component, "PLATFORM_SCHEMA"):
if hasattr(component, "PLATFORM_SCHEMA"): # Entity components have their own warning
# Entity components have their own warning warn_task = None
warn_task = None else:
else: warn_task = hass.loop.call_later(
warn_task = hass.loop.call_later( SLOW_SETUP_WARNING,
SLOW_SETUP_WARNING, _LOGGER.warning,
_LOGGER.warning, "Setup of %s is taking over %s seconds.",
"Setup of %s is taking over %s seconds.", domain,
domain, SLOW_SETUP_WARNING,
SLOW_SETUP_WARNING, )
)
task = None
task = None result = True
result = True try:
try: if hasattr(component, "async_setup"):
if hasattr(component, "async_setup"): task = component.async_setup(hass, processed_config) # type: ignore
task = component.async_setup(hass, processed_config) # type: ignore elif hasattr(component, "setup"):
elif hasattr(component, "setup"): # This should not be replaced with hass.async_add_executor_job because
# 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.
# we don't want to track this task in case it blocks startup. task = hass.loop.run_in_executor(
task = hass.loop.run_in_executor( None, component.setup, hass, processed_config # type: ignore
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 return False
if task: # Flush out async_setup calling create_task. Fragile but covered by test.
async with hass.timeout.async_timeout(SLOW_SETUP_MAX_WAIT, domain): await asyncio.sleep(0)
result = await task await hass.config_entries.flow.async_wait_init_flow_finish(domain)
except asyncio.TimeoutError:
_LOGGER.error( await asyncio.gather(
"Setup of %s is taking longer than %s seconds." *[
" Startup will proceed without waiting any longer", entry.async_setup(hass, integration=integration)
domain, for entry in hass.config_entries.async_entries(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: hass.config.components.add(domain)
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)
# Cleanup # Cleanup
if domain in hass.data[DATA_SETUP]: 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: if domain in BASE_PLATFORMS:
integrations.add(platform) integrations.add(platform)
return integrations 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

View File

@ -1,10 +1,12 @@
"""Tests for WebSocket API commands.""" """Tests for WebSocket API commands."""
import datetime
from unittest.mock import ANY, patch from unittest.mock import ANY, patch
from async_timeout import timeout from async_timeout import timeout
import pytest import pytest
import voluptuous as vol import voluptuous as vol
from homeassistant.bootstrap import SIGNAL_BOOTSTRAP_INTEGRATONS
from homeassistant.components.websocket_api import const from homeassistant.components.websocket_api import const
from homeassistant.components.websocket_api.auth import ( from homeassistant.components.websocket_api.auth import (
TYPE_AUTH, TYPE_AUTH,
@ -15,9 +17,10 @@ from homeassistant.components.websocket_api.const import URL
from homeassistant.core import Context, callback from homeassistant.core import Context, callback
from homeassistant.exceptions import HomeAssistantError from homeassistant.exceptions import HomeAssistantError
from homeassistant.helpers import entity from homeassistant.helpers import entity
from homeassistant.helpers.dispatcher import async_dispatcher_send
from homeassistant.helpers.typing import HomeAssistantType from homeassistant.helpers.typing import HomeAssistantType
from homeassistant.loader import async_get_integration 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 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.service == "test_service"
assert call.data == {"hello": "From variable"} assert call.data == {"hello": "From variable"}
assert call.context.as_dict() == msg_var["result"]["context"] 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},
]

View File

@ -431,7 +431,9 @@ async def test_setup_hass_takes_longer_than_log_slow_startup(
with patch( with patch(
"homeassistant.config.async_hass_config_yaml", "homeassistant.config.async_hass_config_yaml",
return_value={"browser": {}, "frontend": {}}, 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", "homeassistant.components.frontend.async_setup",
side_effect=_async_setup_that_blocks_startup, side_effect=_async_setup_that_blocks_startup,
): ):

View File

@ -1,6 +1,7 @@
"""Test component/platform setup.""" """Test component/platform setup."""
# pylint: disable=protected-access # pylint: disable=protected-access
import asyncio import asyncio
import datetime
import os import os
import threading import threading
from unittest.mock import AsyncMock, Mock, patch 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", {}) 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]