Log which task is blocking startup when debug logging is on (#38134)

* Log which task is blocking startup when debug logging for homeassistant.core is on

* test needs to go one level deeper now
This commit is contained in:
J. Nick Koston 2020-07-23 16:03:42 -10:00 committed by GitHub
parent a5b7a2c228
commit a7459b3126
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
3 changed files with 39 additions and 3 deletions

View file

@ -24,6 +24,7 @@ from typing import (
Callable,
Coroutine,
Dict,
Iterable,
List,
Mapping,
Optional,
@ -99,6 +100,9 @@ CORE_STORAGE_VERSION = 1
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 @@ class HomeAssistant:
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

View file

@ -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

View file

@ -1404,3 +1404,24 @@ async def test_start_events(hass):
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