diff --git a/homeassistant/core.py b/homeassistant/core.py index adeed758555..1d05336e5c4 100644 --- a/homeassistant/core.py +++ b/homeassistant/core.py @@ -393,12 +393,28 @@ class HomeAssistant: """Block until all pending work is done.""" # To flush out any call_soon_threadsafe await asyncio.sleep(0) + start_time: Optional[float] = None while self._pending_tasks: pending = [task for task in self._pending_tasks if not task.done()] self._pending_tasks.clear() if pending: await self._await_and_log_pending(pending) + + if start_time is None: + # Avoid calling monotonic() until we know + # we may need to start logging blocked tasks. + start_time = 0 + elif start_time == 0: + # If we have waited twice then we set the start + # time + start_time = monotonic() + elif monotonic() - start_time > BLOCK_LOG_TIMEOUT: + # We have waited at least three loops and new tasks + # continue to block. At this point we start + # logging all waiting tasks. + for task in pending: + _LOGGER.debug("Waiting for task: %s", task) else: await asyncio.sleep(0) diff --git a/tests/test_core.py b/tests/test_core.py index c144af86804..12ed00fde2c 100644 --- a/tests/test_core.py +++ b/tests/test_core.py @@ -1419,9 +1419,62 @@ async def test_log_blocking_events(hass, caplog): hass.async_create_task(_wait_a_bit_1()) await hass.async_block_till_done() - with patch.object(ha, "BLOCK_LOG_TIMEOUT", 0.00001): + with patch.object(ha, "BLOCK_LOG_TIMEOUT", 0.0001): 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 + + +async def test_chained_logging_hits_log_timeout(hass, caplog): + """Ensure we log which task is blocking startup when there is a task chain and debug logging is on.""" + caplog.set_level(logging.DEBUG) + + created = 0 + + async def _task_chain_1(): + nonlocal created + created += 1 + if created > 10: + return + hass.async_create_task(_task_chain_2()) + + async def _task_chain_2(): + nonlocal created + created += 1 + if created > 10: + return + hass.async_create_task(_task_chain_1()) + + with patch.object(ha, "BLOCK_LOG_TIMEOUT", 0.0001): + hass.async_create_task(_task_chain_1()) + await hass.async_block_till_done() + + assert "_task_chain_" in caplog.text + + +async def test_chained_logging_misses_log_timeout(hass, caplog): + """Ensure we do not log which task is blocking startup if we do not hit the timeout.""" + caplog.set_level(logging.DEBUG) + + created = 0 + + async def _task_chain_1(): + nonlocal created + created += 1 + if created > 10: + return + hass.async_create_task(_task_chain_2()) + + async def _task_chain_2(): + nonlocal created + created += 1 + if created > 10: + return + hass.async_create_task(_task_chain_1()) + + hass.async_create_task(_task_chain_1()) + await hass.async_block_till_done() + + assert "_task_chain_" not in caplog.text