From 1e491291972aa28fbdb39e6fe47a392d2a5ed6be Mon Sep 17 00:00:00 2001 From: Stefan Agner Date: Wed, 1 Nov 2023 21:01:38 +0100 Subject: [PATCH] Use longer timeouts for API checks before trigger a rollback (#4658) * Don't check if Core is running to trigger rollback Currently we check for Core API access and that the state is running. If this is not fulfilled within 5 minutes, we rollback to the previous version. It can take quite a while until Home Assistant Core is in state running. In fact, after going through bootstrap, it can theoretically take indefinitely (as in there is no timeout from Core side). So to trigger rollback, rather than check the state to be running, just check if the API is accessible in this case. This prevents spurious rollbacks. * Check Core status with and timeout after a longer time Instead of checking the Core API just for response, do check the state. Use a timeout which is long enough to cover all stages and other timeouts during Core startup. * Introduce get_api_state and better status messages * Update supervisor/homeassistant/api.py Co-authored-by: J. Nick Koston * Add successful start test --------- Co-authored-by: J. Nick Koston --- supervisor/homeassistant/api.py | 18 +++++++++++------ supervisor/homeassistant/core.py | 32 ++++++++++++++++++++++--------- tests/conftest.py | 1 + tests/homeassistant/test_core.py | 33 ++++++++++++++++++++++++++++---- 4 files changed, 65 insertions(+), 19 deletions(-) diff --git a/supervisor/homeassistant/api.py b/supervisor/homeassistant/api.py index 1885ff56ce0..feb604214ca 100644 --- a/supervisor/homeassistant/api.py +++ b/supervisor/homeassistant/api.py @@ -130,14 +130,14 @@ async def get_core_state(self) -> dict[str, Any]: """Return Home Assistant core state.""" return await self._get_json("api/core/state") - async def check_api_state(self) -> bool: - """Return True if Home Assistant up and running.""" + async def get_api_state(self) -> str | None: + """Return state of Home Assistant Core or None.""" # Skip check on landingpage if ( self.sys_homeassistant.version is None or self.sys_homeassistant.version == LANDINGPAGE ): - return False + return None # Check if port is up if not await self.sys_run_in_executor( @@ -145,7 +145,7 @@ async def check_api_state(self) -> bool: self.sys_homeassistant.ip_address, self.sys_homeassistant.api_port, ): - return False + return None # Check if API is up with suppress(HomeAssistantAPIError): @@ -157,7 +157,13 @@ async def check_api_state(self) -> bool: else: data = await self.get_config() # Older versions of home assistant does not expose the state - if data and data.get("state", "RUNNING") == "RUNNING": - return True + if data: + return data.get("state", "RUNNING") + + return None + async def check_api_state(self) -> bool: + """Return Home Assistant Core state if up.""" + if state := self.get_api_state(): + return state == "RUNNING" return False diff --git a/supervisor/homeassistant/core.py b/supervisor/homeassistant/core.py index 6a5374e5f18..e6a996545b7 100644 --- a/supervisor/homeassistant/core.py +++ b/supervisor/homeassistant/core.py @@ -44,7 +44,10 @@ _LOGGER: logging.Logger = logging.getLogger(__name__) SECONDS_BETWEEN_API_CHECKS: Final[int] = 5 -STARTUP_API_CHECK_TIMEOUT: Final[timedelta] = timedelta(minutes=5) +# Core Stage 1 and some wiggle room +STARTUP_API_RESPONSE_TIMEOUT: Final[timedelta] = timedelta(minutes=3) +# All stages plus event start timeout and some wiggle rooom +STARTUP_API_CHECK_RUNNING_TIMEOUT: Final[timedelta] = timedelta(minutes=15) RE_YAML_ERROR = re.compile(r"homeassistant\.util\.yaml") @@ -440,8 +443,9 @@ async def _block_till_run(self, version: AwesomeVersion) -> None: return _LOGGER.info("Wait until Home Assistant is ready") - start = datetime.now() - while not (timeout := datetime.now() >= start + STARTUP_API_CHECK_TIMEOUT): + deadline = datetime.now() + STARTUP_API_RESPONSE_TIMEOUT + last_state = None + while not (timeout := datetime.now() >= deadline): await asyncio.sleep(SECONDS_BETWEEN_API_CHECKS) # 1: Check if Container is is_running @@ -449,16 +453,26 @@ async def _block_till_run(self, version: AwesomeVersion) -> None: _LOGGER.error("Home Assistant has crashed!") break - # 2: Check if API response - if await self.sys_homeassistant.api.check_api_state(): - _LOGGER.info("Detect a running Home Assistant instance") - self._error_state = False - return + # 2: Check API response + if state := await self.sys_homeassistant.api.get_api_state(): + if last_state is None: + # API initially available, move deadline up and check API + # state to be running now + deadline = datetime.now() + STARTUP_API_CHECK_RUNNING_TIMEOUT + + if last_state != state: + _LOGGER.info("Home Assistant Core state changed to %s", state) + last_state = state + + if state == "RUNNING": + _LOGGER.info("Detect a running Home Assistant instance") + self._error_state = False + return self._error_state = True if timeout: raise HomeAssistantStartupTimeout( - "No API response in 5 minutes, assuming core has had a fatal startup error", + "No Home Assistant Core response, assuming a fatal startup error", _LOGGER.error, ) raise HomeAssistantCrashError() diff --git a/tests/conftest.py b/tests/conftest.py index 03f325672f9..86c3a531eeb 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -354,6 +354,7 @@ async def coresys( # WebSocket coresys_obj.homeassistant.api.check_api_state = AsyncMock(return_value=True) + coresys_obj.homeassistant.api.get_api_state = AsyncMock(return_value="RUNNING") coresys_obj.homeassistant._websocket._client = AsyncMock( ha_version=AwesomeVersion("2021.2.4") ) diff --git a/tests/homeassistant/test_core.py b/tests/homeassistant/test_core.py index e2f89bfdc79..7dbcacc0940 100644 --- a/tests/homeassistant/test_core.py +++ b/tests/homeassistant/test_core.py @@ -275,7 +275,7 @@ async def test_api_check_timeout( """Test attempts to contact the API timeout.""" container.status = "stopped" coresys.homeassistant.version = AwesomeVersion("2023.9.0") - coresys.homeassistant.api.check_api_state.return_value = False + coresys.homeassistant.api.get_api_state.return_value = None async def mock_instance_start(*_): container.status = "running" @@ -294,8 +294,33 @@ async def mock_sleep(*args): ), pytest.raises(HomeAssistantCrashError): await coresys.homeassistant.core.start() - assert coresys.homeassistant.api.check_api_state.call_count == 5 + assert coresys.homeassistant.api.get_api_state.call_count == 3 assert ( - "No API response in 5 minutes, assuming core has had a fatal startup error" - in caplog.text + "No Home Assistant Core response, assuming a fatal startup error" in caplog.text ) + + +async def test_api_check_success( + coresys: CoreSys, container: MagicMock, caplog: pytest.LogCaptureFixture +): + """Test attempts to contact the API timeout.""" + container.status = "stopped" + coresys.homeassistant.version = AwesomeVersion("2023.9.0") + + async def mock_instance_start(*_): + container.status = "running" + + with patch.object( + DockerHomeAssistant, "start", new=mock_instance_start + ), patch.object(DockerAPI, "container_is_initialized", return_value=True), travel( + datetime(2023, 10, 2, 0, 0, 0), tick=False + ) as traveller: + + async def mock_sleep(*args): + traveller.shift(timedelta(minutes=1)) + + with patch("supervisor.homeassistant.core.asyncio.sleep", new=mock_sleep): + await coresys.homeassistant.core.start() + + assert coresys.homeassistant.api.get_api_state.call_count == 1 + assert "Detect a running Home Assistant instance" in caplog.text