Periodically log when integrations are taking a while to setup (home-…

…assistant#36208)

* Periodicly log when intergrations are taking a while to setup

When one or more intergrations are taking a while to setup
it is hard to determine which one is the cause.  We can
help narrow this down for the user with a periodic log
message about which domains are still waiting to be setup
every 30s.

* 30 -> 60 per discussion

* only log when the integration is actually doing setup

* reduce, fix race in test

homeassistant/bootstrap.py

@@ -20,7 +20,7 @@
 )
 from homeassistant.exceptions import HomeAssistantError
 from homeassistant.helpers.typing import ConfigType
-from homeassistant.setup import DATA_SETUP, async_setup_component
+from homeassistant.setup import DATA_SETUP, DATA_SETUP_STARTED, async_setup_component
 from homeassistant.util.logging import async_activate_log_queue_handler
 from homeassistant.util.package import async_get_user_site, is_virtual_env
 from homeassistant.util.yaml import clear_secret_cache
@@ -32,6 +32,8 @@
 # hass.data key for logging information.
 DATA_LOGGING = "logging"
 
+LOG_SLOW_STARTUP_INTERVAL = 60
+
 DEBUGGER_INTEGRATIONS = {"ptvsd"}
 CORE_INTEGRATIONS = ("homeassistant", "persistent_notification")
 LOGGING_INTEGRATIONS = {"logger", "system_log", "sentry"}
@@ -323,13 +325,30 @@ async def _async_set_up_integrations(
 ) -> None:
     """Set up all the integrations."""
 
+    setup_started = hass.data[DATA_SETUP_STARTED] = {}
+
     async def async_setup_multi_components(domains: Set[str]) -> None:
         """Set up multiple domains. Log on failure."""
+
+        async def _async_log_pending_setups() -> None:
+            """Periodic log of setups that are pending for longer than LOG_SLOW_STARTUP_INTERVAL."""
+            while True:
+                await asyncio.sleep(LOG_SLOW_STARTUP_INTERVAL)
+                remaining = [domain for domain in domains if domain in setup_started]
+
+                if remaining:
+                    _LOGGER.info(
+                        "Waiting on integrations to complete setup: %s",
+                        ", ".join(remaining),
+                    )
+
         futures = {
             domain: hass.async_create_task(async_setup_component(hass, domain, config))
             for domain in domains
         }
+        log_task = hass.loop.create_task(_async_log_pending_setups())
         await asyncio.wait(futures.values())
+        log_task.cancel()
         errors = [domain for domain in domains if futures[domain].exception()]
         for domain in errors:
             exception = futures[domain].exception()

homeassistant/setup.py

@@ -10,11 +10,13 @@
 from homeassistant.const import EVENT_COMPONENT_LOADED, PLATFORM_FORMAT
 from homeassistant.exceptions import HomeAssistantError
 from homeassistant.helpers.typing import ConfigType
+from homeassistant.util import dt as dt_util
 
 _LOGGER = logging.getLogger(__name__)
 
 ATTR_COMPONENT = "component"
 
+DATA_SETUP_STARTED = "setup_started"
 DATA_SETUP = "setup_tasks"
 DATA_DEPS_REQS = "deps_reqs_processed"
 
@@ -155,6 +157,7 @@ def log_error(msg: str, link: Optional[str] = None) -> None:
 
     start = timer()
     _LOGGER.info("Setting up %s", domain)
+    hass.data.setdefault(DATA_SETUP_STARTED, {})[domain] = dt_util.utcnow()
 
     if hasattr(component, "PLATFORM_SCHEMA"):
         # Entity components have their own warning
@@ -181,6 +184,7 @@ def log_error(msg: str, link: Optional[str] = None) -> None:
             )
         else:
             log_error("No setup function defined.")
+            hass.data[DATA_SETUP_STARTED].pop(domain)
             return False
 
         result = await asyncio.wait_for(task, SLOW_SETUP_MAX_WAIT)
@@ -191,10 +195,12 @@ def log_error(msg: str, link: Optional[str] = None) -> None:
             domain,
             SLOW_SETUP_MAX_WAIT,
         )
+        hass.data[DATA_SETUP_STARTED].pop(domain)
         return False
     except Exception:  # pylint: disable=broad-except
         _LOGGER.exception("Error during setup of component %s", domain)
         async_notify_setup_error(hass, domain, integration.documentation)
+        hass.data[DATA_SETUP_STARTED].pop(domain)
         return False
     finally:
         end = timer()
@@ -204,12 +210,14 @@ def log_error(msg: str, link: Optional[str] = None) -> None:
 
     if result is False:
         log_error("Integration failed to initialize.")
+        hass.data[DATA_SETUP_STARTED].pop(domain)
         return False
     if result is not True:
         log_error(
             f"Integration {domain!r} did not return boolean if setup was "
             "successful. Disabling component."
         )
+        hass.data[DATA_SETUP_STARTED].pop(domain)
         return False
 
     # Flush out async_setup calling create_task. Fragile but covered by test.
@@ -224,6 +232,7 @@ def log_error(msg: str, link: Optional[str] = None) -> None:
     )
 
     hass.config.components.add(domain)
+    hass.data[DATA_SETUP_STARTED].pop(domain)
 
     # Cleanup
     if domain in hass.data[DATA_SETUP]:

tests/test_bootstrap.py

@@ -1,5 +1,6 @@
 """Test the bootstrapping."""
 # pylint: disable=protected-access
+import asyncio
 import logging
 import os
 from unittest.mock import Mock
@@ -249,6 +250,7 @@ async def test_setup_hass(
     mock_mount_local_lib_path,
     mock_ensure_config_exists,
     mock_process_ha_config_upgrade,
+    caplog,
 ):
     """Test it works."""
     verbose = Mock()
@@ -259,7 +261,7 @@ async def test_setup_hass(
     with patch(
         "homeassistant.config.async_hass_config_yaml",
         return_value={"browser": {}, "frontend": {}},
-    ):
+    ), patch.object(bootstrap, "LOG_SLOW_STARTUP_INTERVAL", 5000):
         hass = await bootstrap.async_setup_hass(
             config_dir=get_test_config_dir(),
             verbose=verbose,
@@ -270,6 +272,8 @@ async def test_setup_hass(
             safe_mode=False,
         )
 
+    assert "Waiting on integrations to complete setup" not in caplog.text
+
     assert "browser" in hass.config.components
     assert "safe_mode" not in hass.config.components
 
@@ -286,6 +290,44 @@ async def test_setup_hass(
     assert len(mock_process_ha_config_upgrade.mock_calls) == 1
 
 
+async def test_setup_hass_takes_longer_than_log_slow_startup(
+    mock_enable_logging,
+    mock_is_virtual_env,
+    mock_mount_local_lib_path,
+    mock_ensure_config_exists,
+    mock_process_ha_config_upgrade,
+    caplog,
+):
+    """Test it works."""
+    verbose = Mock()
+    log_rotate_days = Mock()
+    log_file = Mock()
+    log_no_color = Mock()
+
+    async def _async_setup_that_blocks_startup(*args, **kwargs):
+        await asyncio.sleep(0.6)
+        return True
+
+    with patch(
+        "homeassistant.config.async_hass_config_yaml",
+        return_value={"browser": {}, "frontend": {}},
+    ), patch.object(bootstrap, "LOG_SLOW_STARTUP_INTERVAL", 0.3), patch(
+        "homeassistant.components.frontend.async_setup",
+        side_effect=_async_setup_that_blocks_startup,
+    ):
+        await bootstrap.async_setup_hass(
+            config_dir=get_test_config_dir(),
+            verbose=verbose,
+            log_rotate_days=log_rotate_days,
+            log_file=log_file,
+            log_no_color=log_no_color,
+            skip_pip=True,
+            safe_mode=False,
+        )
+
+    assert "Waiting on integrations to complete setup" in caplog.text
+
+
 async def test_setup_hass_invalid_yaml(
     mock_enable_logging,
     mock_is_virtual_env,