evlli/hass-core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Log waiting tasks in bootstrap that are delaying startup (#112637)

Browse source
This commit is contained in:
J. Nick Koston 2024-03-07 13:18:18 -10:00 • committed by GitHub
parent 27af6f1466
commit 5da629b3e5
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
3 changed files with 110 additions and 7 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

20
homeassistant/bootstrap.py
View file

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

12
homeassistant/core.py
View file

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

85
tests/test_bootstrap.py
View file

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