diff --git a/homeassistant/core.py b/homeassistant/core.py index 18493d85629a0..adeed7585552b 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -24,6 +24,7 @@ Callable, Coroutine, Dict, + Iterable, List, Mapping, Optional, @@ -99,6 +100,9 @@ DOMAIN = "homeassistant" +# How long to wait to log tasks that are blocking +BLOCK_LOG_TIMEOUT = 60 + # How long we wait for the result of a service call SERVICE_CALL_LIMIT = 10 # seconds @@ -394,10 +398,21 @@ async def async_block_till_done(self) -> None: pending = [task for task in self._pending_tasks if not task.done()] self._pending_tasks.clear() if pending: - await asyncio.wait(pending) + await self._await_and_log_pending(pending) else: await asyncio.sleep(0) + async def _await_and_log_pending(self, pending: Iterable[Awaitable[Any]]) -> None: + """Await and log tasks that take a long time.""" + wait_time = 0 + while pending: + _, pending = await asyncio.wait(pending, timeout=BLOCK_LOG_TIMEOUT) + if not pending: + return + wait_time += BLOCK_LOG_TIMEOUT + for task in pending: + _LOGGER.debug("Waited %s seconds for task: %s", wait_time, task) + def stop(self) -> None: """Stop Home Assistant and shuts down all threads.""" if self.state == CoreState.not_running: # just ignore diff --git a/tests/helpers/test_entity_platform.py b/tests/helpers/test_entity_platform.py index d5b817e0655e6..ddecd1988eda7 100644 --- a/tests/helpers/test_entity_platform.py +++ b/tests/helpers/test_entity_platform.py @@ -188,8 +188,8 @@ async def test_platform_warn_slow_setup(hass): assert mock_call.called # mock_calls[0] is the warning message for component setup - # mock_calls[5] is the warning message for platform setup - timeout, logger_method = mock_call.mock_calls[5][1][:2] + # mock_calls[6] is the warning message for platform setup + timeout, logger_method = mock_call.mock_calls[6][1][:2] assert timeout == entity_platform.SLOW_SETUP_WARNING assert logger_method == _LOGGER.warning diff --git a/tests/test_core.py b/tests/test_core.py index 01a751b657060..c144af86804e1 100644 --- a/tests/test_core.py +++ b/tests/test_core.py @@ -1404,3 +1404,24 @@ def capture_core_state(_): EVENT_HOMEASSISTANT_STARTED, ] assert core_states == [ha.CoreState.starting, ha.CoreState.running] + + +async def test_log_blocking_events(hass, caplog): + """Ensure we log which task is blocking startup when debug logging is on.""" + caplog.set_level(logging.DEBUG) + + async def _wait_a_bit_1(): + await asyncio.sleep(0.1) + + async def _wait_a_bit_2(): + await asyncio.sleep(0.1) + + hass.async_create_task(_wait_a_bit_1()) + await hass.async_block_till_done() + + with patch.object(ha, "BLOCK_LOG_TIMEOUT", 0.00001): + hass.async_create_task(_wait_a_bit_2()) + await hass.async_block_till_done() + + assert "_wait_a_bit_2" in caplog.text + assert "_wait_a_bit_1" not in caplog.text