diff --git a/homeassistant/bootstrap.py b/homeassistant/bootstrap.py index 446fe73f926..28eb45e5273 100644 --- a/homeassistant/bootstrap.py +++ b/homeassistant/bootstrap.py @@ -606,7 +606,10 @@ class _WatchPendingSetups: domain: (now - start_time) for domain, start_time in self._setup_started.items() } - _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) + if remaining_with_setup_started: + _LOGGER.debug("Integration remaining: %s", remaining_with_setup_started) + elif waiting_tasks := self._hass._active_tasks: # pylint: disable=protected-access + _LOGGER.debug("Waiting on tasks: %s", waiting_tasks) self._async_dispatch(remaining_with_setup_started) if ( self._setup_started @@ -849,7 +852,10 @@ async def _async_set_up_integrations( ): await async_setup_multi_components(hass, stage_1_domains, config) except TimeoutError: - _LOGGER.warning("Setup timed out for stage 1 - moving forward") + _LOGGER.warning( + "Setup timed out for stage 1 waiting on %s - moving forward", + hass._active_tasks, # pylint: disable=protected-access + ) # Add after dependencies when setting up stage 2 domains async_set_domains_to_be_loaded(hass, stage_2_domains) @@ -862,7 +868,10 @@ async def _async_set_up_integrations( ): await async_setup_multi_components(hass, stage_2_domains, config) except TimeoutError: - _LOGGER.warning("Setup timed out for stage 2 - moving forward") + _LOGGER.warning( + "Setup timed out for stage 2 waiting on %s - moving forward", + hass._active_tasks, # pylint: disable=protected-access + ) # Wrap up startup _LOGGER.debug("Waiting for startup to wrap up") @@ -870,7 +879,10 @@ async def _async_set_up_integrations( async with hass.timeout.async_timeout(WRAP_UP_TIMEOUT, cool_down=COOLDOWN_TIME): await hass.async_block_till_done() except TimeoutError: - _LOGGER.warning("Setup timed out for bootstrap - moving forward") + _LOGGER.warning( + "Setup timed out for bootstrap waiting on %s - moving forward", + hass._active_tasks, # pylint: disable=protected-access + ) watcher.async_stop() diff --git a/homeassistant/core.py b/homeassistant/core.py index f0b10760228..3a60e6f1170 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -402,6 +402,18 @@ class HomeAssistant: max_workers=1, thread_name_prefix="ImportExecutor" ) + @property + def _active_tasks(self) -> set[asyncio.Future[Any]]: + """Return all active tasks. + + This property is used in bootstrap to log all active tasks + so we can identify what is blocking startup. + + This property is marked as private to avoid accidental use + as it is not guaranteed to be present in future versions. + """ + return self._tasks + @cached_property def is_running(self) -> bool: """Return if Home Assistant is running.""" diff --git a/tests/test_bootstrap.py b/tests/test_bootstrap.py index 550eb4bffee..83722566590 100644 --- a/tests/test_bootstrap.py +++ b/tests/test_bootstrap.py @@ -844,10 +844,10 @@ async def test_warning_logged_on_wrap_up_timeout( def gen_domain_setup(domain): async def async_setup(hass, config): - async def _background_task(): + async def _not_marked_background_task(): await asyncio.sleep(0.2) - hass.async_create_task(_background_task()) + hass.async_create_task(_not_marked_background_task()) return True return async_setup @@ -865,7 +865,86 @@ async def test_warning_logged_on_wrap_up_timeout( await bootstrap._async_set_up_integrations(hass, {"normal_integration": {}}) await hass.async_block_till_done() - assert "Setup timed out for bootstrap - moving forward" in caplog.text + assert "Setup timed out for bootstrap" in caplog.text + assert "waiting on" in caplog.text + assert "_not_marked_background_task" in caplog.text + + +@pytest.mark.parametrize("load_registries", [False]) +async def test_tasks_logged_that_block_stage_1( + hass: HomeAssistant, caplog: pytest.LogCaptureFixture +) -> None: + """Test we log tasks that delay stage 1 startup.""" + + def gen_domain_setup(domain): + async def async_setup(hass, config): + async def _not_marked_background_task(): + await asyncio.sleep(0.2) + + hass.async_create_task(_not_marked_background_task()) + await asyncio.sleep(0.1) + return True + + return async_setup + + mock_integration( + hass, + MockModule( + domain="normal_integration", + async_setup=gen_domain_setup("normal_integration"), + partial_manifest={}, + ), + ) + + original_stage_1 = bootstrap.STAGE_1_INTEGRATIONS + with patch.object(bootstrap, "STAGE_1_TIMEOUT", 0), patch.object( + bootstrap, "COOLDOWN_TIME", 0 + ), patch.object( + bootstrap, "STAGE_1_INTEGRATIONS", [*original_stage_1, "normal_integration"] + ): + await bootstrap._async_set_up_integrations(hass, {"normal_integration": {}}) + await hass.async_block_till_done() + + assert "Setup timed out for stage 1 waiting on" in caplog.text + assert "waiting on" in caplog.text + assert "_not_marked_background_task" in caplog.text + + +@pytest.mark.parametrize("load_registries", [False]) +async def test_tasks_logged_that_block_stage_2( + hass: HomeAssistant, caplog: pytest.LogCaptureFixture +) -> None: + """Test we log tasks that delay stage 2 startup.""" + + def gen_domain_setup(domain): + async def async_setup(hass, config): + async def _not_marked_background_task(): + await asyncio.sleep(0.2) + + hass.async_create_task(_not_marked_background_task()) + await asyncio.sleep(0.1) + return True + + return async_setup + + mock_integration( + hass, + MockModule( + domain="normal_integration", + async_setup=gen_domain_setup("normal_integration"), + partial_manifest={}, + ), + ) + + with patch.object(bootstrap, "STAGE_2_TIMEOUT", 0), patch.object( + bootstrap, "COOLDOWN_TIME", 0 + ): + await bootstrap._async_set_up_integrations(hass, {"normal_integration": {}}) + await hass.async_block_till_done() + + assert "Setup timed out for stage 2 waiting on" in caplog.text + assert "waiting on" in caplog.text + assert "_not_marked_background_task" in caplog.text @pytest.mark.parametrize("load_registries", [False])