From 09a72ac505703ebb9bff2284050b6e86bdb4e3fa Mon Sep 17 00:00:00 2001 From: Christian Lackas Date: Mon, 15 Jun 2026 16:08:40 +0200 Subject: [PATCH] homematicip_cloud: harden post-reconnect state recovery using 2.9.0 diagnostics (#169526) --- .../homematicip_cloud/diagnostics.py | 5 +- .../components/homematicip_cloud/hap.py | 131 ++++++-- .../snapshots/test_diagnostics.ambr | 52 ++-- .../components/homematicip_cloud/test_hap.py | 279 ++++++++++++++---- 4 files changed, 353 insertions(+), 114 deletions(-) diff --git a/homeassistant/components/homematicip_cloud/diagnostics.py b/homeassistant/components/homematicip_cloud/diagnostics.py index 752384fcc618..5a61bb8855a1 100644 --- a/homeassistant/components/homematicip_cloud/diagnostics.py +++ b/homeassistant/components/homematicip_cloud/diagnostics.py @@ -22,4 +22,7 @@ async def async_get_config_entry_diagnostics( anonymized = handle_config(json_state, anonymize=True) config = json.loads(anonymized) - return async_redact_data(config, TO_REDACT_CONFIG) + return { + "websocket": hap.websocket_diagnostics(), + "config": async_redact_data(config, TO_REDACT_CONFIG), + } diff --git a/homeassistant/components/homematicip_cloud/hap.py b/homeassistant/components/homematicip_cloud/hap.py index b003f9a085c7..df54e669a584 100644 --- a/homeassistant/components/homematicip_cloud/hap.py +++ b/homeassistant/components/homematicip_cloud/hap.py @@ -164,9 +164,11 @@ class HomematicipHAP: self.set_all_to_unavailable() elif self._ws_connection_closed.is_set(): _LOGGER.info("HMIP access point has reconnected to the cloud") - self._get_state_task = self.hass.async_create_task(self._try_get_state()) - self._get_state_task.add_done_callback(self.get_state_finished) - self._ws_connection_closed.clear() + _LOGGER.debug( + "HMIP websocket diagnostics: %s", + self._websocket_diagnostic_context(), + ) + self._start_get_state_task() @callback def async_create_entity(self, *args, **kwargs) -> None: @@ -180,44 +182,103 @@ class HomematicipHAP: await asyncio.sleep(30) await self.hass.config_entries.async_reload(self.config_entry.entry_id) + def websocket_diagnostics(self) -> dict[str, Any]: + """Return websocket diagnostics dict (None values omitted).""" + diagnostics = { + "last_disconnect_reason": self.home.websocket_last_disconnect_reason(), + "reconnect_attempts": self.home.websocket_reconnect_attempt_count(), + "seconds_since_last_message": ( + self.home.websocket_seconds_since_last_message() + ), + "message_count": self.home.websocket_message_count(), + } + return {k: v for k, v in diagnostics.items() if v is not None} + + def _websocket_diagnostic_context(self) -> str: + """Return a single-line summary of websocket diagnostics for logs.""" + diagnostics = self.websocket_diagnostics() + if not diagnostics: + return "no diagnostics available" + return ", ".join(f"{k}={v!r}" for k, v in diagnostics.items()) + + @callback + def _start_get_state_task(self) -> None: + """Cancel any in-flight reconnect refresh and start a new one.""" + if self._get_state_task is not None and not self._get_state_task.done(): + _LOGGER.debug( + "Cancelling previous HomematicIP reconnect state refresh task" + ) + self._get_state_task.cancel() + + self._get_state_task = self.hass.async_create_task(self._try_get_state()) + self._get_state_task.add_done_callback(self.get_state_finished) + self._ws_connection_closed.clear() + async def _try_get_state(self) -> None: - """Call get_state in a loop until no error occurs. + """Refresh state after a websocket reconnect. - Uses exponential backoff on error. + Delegates the bounded websocket wait + retry-with-exponential-backoff + to the homematicip library (``refresh_state_after_reconnect_async``), + and only handles HA-specific concerns here: + - on authentication failure, trigger reauth + - clear the per-device ``unreach`` flag and signal entity updates + (the workaround for core#160048) """ + try: + await self.home.refresh_state_after_reconnect_async() + except HmipAuthenticationError: + _LOGGER.error( + "Authentication error from HomematicIP Cloud, triggering reauth" + ) + self.config_entry.async_start_reauth(self.hass) + return + self._post_state_refresh() - # Wait until WebSocket connection is established. - while not self.home.websocket_is_connected(): - await asyncio.sleep(2) + async def _on_websocket_stale(self, severity: str, seconds_since: float) -> None: + """Log a websocket-stale event surfaced by the library. - delay = 8 - max_delay = 1500 - while True: - try: - await self.get_state() - break - except HmipAuthenticationError: - _LOGGER.error( - "Authentication error from HomematicIP Cloud, triggering reauth" - ) - self.config_entry.async_start_reauth(self.hass) - break - except HmipConnectionError as err: - _LOGGER.warning( - "Get_state failed, retrying in %s seconds: %s", delay, err - ) - await asyncio.sleep(delay) - delay = min(delay * 2, max_delay) + The library polls staleness internally and fires this callback once + per severity per stuck period; it re-arms when fresh messages arrive. + We just translate severity to a log level. + """ + log = _LOGGER.error if severity == "error" else _LOGGER.warning + log( + "HomematicIP websocket has not received a message for " + "%.0f seconds while reporting connected", + seconds_since, + ) + _LOGGER.debug( + "HMIP websocket diagnostics: %s", + self._websocket_diagnostic_context(), + ) async def get_state(self) -> None: """Update HMIP state and tell Home Assistant.""" await self.home.get_current_state_async() + self._post_state_refresh() + + def _post_state_refresh(self) -> None: + """Apply HA-specific post-processing after a state refresh. + + ``set_all_to_unavailable`` marked every device unreach=True on + disconnect; ``get_current_state_async`` only clears that flag for + devices whose state actually changed during the outage, so the rest + stay stuck unavailable after reconnect. Force-clear for all devices. + Trade-off: a device that is *genuinely* unreachable on the cloud + side will briefly appear available until its next state push + corrects it. That self-corrects, while the previous behaviour left + entities stuck unavailable indefinitely (core #160048). + """ + for device in self.home.devices: + device.unreach = False self.update_all() def get_state_finished(self, future) -> None: """Execute when try_get_state coroutine has finished.""" try: future.result() + except asyncio.CancelledError: + _LOGGER.debug("HomematicIP reconnect state refresh task was cancelled") except Exception as err: # noqa: BLE001 _LOGGER.error( "Error updating state after HMIP access point reconnect: %s", err @@ -246,6 +307,7 @@ class HomematicipHAP: home.set_on_connected_handler(self.ws_connected_handler) home.set_on_disconnected_handler(self.ws_disconnected_handler) home.set_on_reconnect_handler(self.ws_reconnected_handler) + home.set_on_websocket_stale_handler(self._on_websocket_stale) async def async_reset(self) -> bool: """Close the websocket connection.""" @@ -275,23 +337,28 @@ class HomematicipHAP: """Handle websocket connected.""" _LOGGER.info("Websocket connection to HomematicIP Cloud established") if self._ws_connection_closed.is_set(): - self._get_state_task = self.hass.async_create_task(self._try_get_state()) - self._get_state_task.add_done_callback(self.get_state_finished) - - self._ws_connection_closed.clear() + self._start_get_state_task() async def ws_disconnected_handler(self) -> None: """Handle websocket disconnection.""" _LOGGER.warning("Websocket connection to HomematicIP Cloud closed") + _LOGGER.debug( + "HMIP websocket diagnostics: %s", + self._websocket_diagnostic_context(), + ) self._ws_connection_closed.set() async def ws_reconnected_handler(self, reason: str) -> None: """Handle websocket reconnection.""" _LOGGER.info( - "Websocket connection to HomematicIP Cloud trying" - " to reconnect due to reason: %s", + "Websocket connection to HomematicIP Cloud trying to reconnect due to " + "reason: %s", reason, ) + _LOGGER.debug( + "HMIP websocket diagnostics: %s", + self._websocket_diagnostic_context(), + ) self._ws_connection_closed.set() diff --git a/tests/components/homematicip_cloud/snapshots/test_diagnostics.ambr b/tests/components/homematicip_cloud/snapshots/test_diagnostics.ambr index 4cdedde3273e..d648782eb4fd 100644 --- a/tests/components/homematicip_cloud/snapshots/test_diagnostics.ambr +++ b/tests/components/homematicip_cloud/snapshots/test_diagnostics.ambr @@ -1,32 +1,38 @@ # serializer version: 1 # name: test_diagnostics dict({ - 'accessPointId': '3014F7110000000000000000', - 'clients': dict({ - '00000000-0000-0000-0000-000000000000': dict({ + 'config': dict({ + 'accessPointId': '3014F7110000000000000000', + 'clients': dict({ + '00000000-0000-0000-0000-000000000000': dict({ + 'id': '00000000-0000-0000-0000-000000000000', + 'label': 'Home Assistant', + 'refreshToken': None, + }), + }), + 'devices': dict({ + '3014F7110000000000000001': dict({ + 'id': '3014F7110000000000000001', + 'label': 'Living Room Thermostat', + 'serializedGlobalTradeItemNumber': '3014F7110000000000000002', + 'type': 'WALL_MOUNTED_THERMOSTAT_PRO', + }), + }), + 'home': dict({ 'id': '00000000-0000-0000-0000-000000000000', - 'label': 'Home Assistant', - 'refreshToken': None, + 'location': dict({ + 'city': '**REDACTED**', + 'latitude': '**REDACTED**', + 'longitude': '**REDACTED**', + }), + 'weather': dict({ + 'temperature': 18.3, + }), }), }), - 'devices': dict({ - '3014F7110000000000000001': dict({ - 'id': '3014F7110000000000000001', - 'label': 'Living Room Thermostat', - 'serializedGlobalTradeItemNumber': '3014F7110000000000000002', - 'type': 'WALL_MOUNTED_THERMOSTAT_PRO', - }), - }), - 'home': dict({ - 'id': '00000000-0000-0000-0000-000000000000', - 'location': dict({ - 'city': '**REDACTED**', - 'latitude': '**REDACTED**', - 'longitude': '**REDACTED**', - }), - 'weather': dict({ - 'temperature': 18.3, - }), + 'websocket': dict({ + 'message_count': 0, + 'reconnect_attempts': 0, }), }) # --- diff --git a/tests/components/homematicip_cloud/test_hap.py b/tests/components/homematicip_cloud/test_hap.py index 496455823b5c..85a73db8fdeb 100644 --- a/tests/components/homematicip_cloud/test_hap.py +++ b/tests/components/homematicip_cloud/test_hap.py @@ -1,5 +1,6 @@ """Test HomematicIP Cloud accesspoint.""" +import asyncio from unittest.mock import AsyncMock, MagicMock, Mock, patch from homematicip.auth import Auth @@ -240,36 +241,27 @@ async def test_auth_create_exception(hass: HomeAssistant, simple_mock_auth) -> N async def test_get_state_after_disconnect( hass: HomeAssistant, hmip_config_entry: MockConfigEntry, simple_mock_home ) -> None: - """Test get state after disconnect.""" + """ws_connected after a disconnect triggers a state refresh via the library.""" hass.config.components.add(DOMAIN) hap = HomematicipHAP(hass, hmip_config_entry) assert hap simple_mock_home = AsyncMock(spec=AsyncHome, autospec=True) + simple_mock_home.devices = [] hap.home = simple_mock_home - hap.home.websocket_is_connected = Mock(side_effect=[False, True]) - - with ( - patch("asyncio.sleep", new=AsyncMock()) as mock_sleep, - patch.object(hap, "get_state") as mock_get_state, - ): - assert not hap._ws_connection_closed.is_set() - - await hap.ws_connected_handler() - mock_get_state.assert_not_called() - - await hap.ws_disconnected_handler() - assert hap._ws_connection_closed.is_set() - with patch( - "homeassistant.components.homematicip_cloud.hap.AsyncHome.websocket_is_connected", - return_value=True, - ): - await hap.ws_connected_handler() - mock_get_state.assert_called_once() assert not hap._ws_connection_closed.is_set() - hap.home.websocket_is_connected.assert_called() - mock_sleep.assert_awaited_with(2) + + await hap.ws_connected_handler() + simple_mock_home.refresh_state_after_reconnect_async.assert_not_called() + + await hap.ws_disconnected_handler() + assert hap._ws_connection_closed.is_set() + + await hap.ws_connected_handler() + await hass.async_block_till_done() + simple_mock_home.refresh_state_after_reconnect_async.assert_called_once() + assert not hap._ws_connection_closed.is_set() async def test_get_state_after_ap_reconnect( @@ -288,48 +280,42 @@ async def test_get_state_after_ap_reconnect( simple_mock_home = MagicMock(spec=AsyncHome) simple_mock_home.devices = [] - simple_mock_home.websocket_is_connected = Mock(return_value=True) + simple_mock_home.refresh_state_after_reconnect_async = AsyncMock() hap.home = simple_mock_home - with patch.object(hap, "get_state") as mock_get_state: - # Initially not disconnected - assert not hap._ws_connection_closed.is_set() + # Initially not disconnected + assert not hap._ws_connection_closed.is_set() - # Access point loses cloud connection - hap.home.connected = False - hap.async_update() - assert hap._ws_connection_closed.is_set() - mock_get_state.assert_not_called() + # Access point loses cloud connection + hap.home.connected = False + hap.async_update() + assert hap._ws_connection_closed.is_set() + simple_mock_home.refresh_state_after_reconnect_async.assert_not_called() - # Access point reconnects to cloud - hap.home.connected = True - hap.async_update() - - # Let _try_get_state run - await hass.async_block_till_done() - mock_get_state.assert_called_once() + # Access point reconnects to cloud + hap.home.connected = True + hap.async_update() + # Let _try_get_state run + await hass.async_block_till_done() + simple_mock_home.refresh_state_after_reconnect_async.assert_called_once() assert not hap._ws_connection_closed.is_set() -async def test_try_get_state_exponential_backoff() -> None: - """Test _try_get_state waits for websocket connection.""" - - # Arrange: Create instance and mock home +async def test_try_get_state_delegates_to_library_then_post_processes() -> None: + """_try_get_state calls refresh_state_after_reconnect_async then runs post-processing.""" hap = HomematicipHAP(MagicMock(), MagicMock()) hap.home = MagicMock() - hap.home.websocket_is_connected = Mock(return_value=True) + hap.home.refresh_state_after_reconnect_async = AsyncMock() + device_changed = MagicMock(unreach=False) + device_unchanged = MagicMock(unreach=True) + hap.home.devices = [device_changed, device_unchanged] - hap.get_state = AsyncMock( - side_effect=[HmipConnectionError, HmipConnectionError, True] - ) + await hap._try_get_state() - with patch("asyncio.sleep", new=AsyncMock()) as mock_sleep: - await hap._try_get_state() - - assert mock_sleep.mock_calls[0].args[0] == 8 - assert mock_sleep.mock_calls[1].args[0] == 16 - assert hap.get_state.call_count == 3 + hap.home.refresh_state_after_reconnect_async.assert_awaited_once() + assert device_changed.unreach is False + assert device_unchanged.unreach is False async def test_try_get_state_handle_exception() -> None: @@ -371,25 +357,202 @@ async def test_async_connect( async def test_try_get_state_auth_error_triggers_reauth( hass: HomeAssistant, hmip_config_entry: MockConfigEntry, simple_mock_home ) -> None: - """Test _try_get_state stops retrying on auth error and triggers reauth.""" + """An auth error from the library triggers a reauth flow without post-processing.""" hass.config.components.add(DOMAIN) hmip_config_entry.add_to_hass(hass) hap = HomematicipHAP(hass, hmip_config_entry) assert hap hap.home = MagicMock(spec=AsyncHome) - hap.home.websocket_is_connected = Mock(return_value=True) - - hap.get_state = AsyncMock(side_effect=HmipAuthenticationError) + hap.home.devices = [MagicMock(unreach=True)] + hap.home.refresh_state_after_reconnect_async = AsyncMock( + side_effect=HmipAuthenticationError + ) assert not hass.config_entries.flow.async_progress_by_handler(DOMAIN) await hap._try_get_state() await hass.async_block_till_done() - # Should have called get_state only once (no retries) - assert hap.get_state.call_count == 1 + # Auth error path: post-processing must NOT have run. + assert hap.home.devices[0].unreach is True # Should have triggered a reauth flow flows = hass.config_entries.flow.async_progress_by_handler(DOMAIN) assert len(flows) == 1 assert flows[0]["context"]["source"] == "reauth" + + +def _set_diagnostic_defaults(home: MagicMock) -> None: + """Configure quiet defaults for diagnostic methods on a mocked AsyncHome.""" + home.websocket_last_disconnect_reason = Mock(return_value=None) + home.websocket_reconnect_attempt_count = Mock(return_value=None) + home.websocket_seconds_since_last_message = Mock(return_value=None) + home.websocket_message_count = Mock(return_value=None) + + +async def test_start_get_state_task_cancels_existing_task( + hass: HomeAssistant, hmip_config_entry: MockConfigEntry +) -> None: + """Starting a reconnect refresh cancels any in-flight refresh.""" + hass.config.components.add(DOMAIN) + hap = HomematicipHAP(hass, hmip_config_entry) + hap.home = MagicMock(spec=AsyncHome) + + old_task = MagicMock() + old_task.done.return_value = False + hap._get_state_task = old_task + + with patch.object(hap, "_try_get_state", new=AsyncMock()): + hap._start_get_state_task() + + old_task.cancel.assert_called_once() + assert hap._get_state_task is not old_task + assert not hap._ws_connection_closed.is_set() + + +async def test_start_get_state_task_skips_cancel_for_completed_task( + hass: HomeAssistant, hmip_config_entry: MockConfigEntry +) -> None: + """Starting a reconnect refresh does not cancel a completed task.""" + hass.config.components.add(DOMAIN) + hap = HomematicipHAP(hass, hmip_config_entry) + hap.home = MagicMock(spec=AsyncHome) + + old_task = MagicMock() + old_task.done.return_value = True + hap._get_state_task = old_task + + with patch.object(hap, "_try_get_state", new=AsyncMock()): + hap._start_get_state_task() + + old_task.cancel.assert_not_called() + + +async def test_replaced_get_state_task_cancellation_is_not_logged_as_error( + hass: HomeAssistant, hmip_config_entry: MockConfigEntry +) -> None: + """Replacing an in-flight refresh must not log the cancelled task as error.""" + hass.config.components.add(DOMAIN) + hap = HomematicipHAP(hass, hmip_config_entry) + hap.home = MagicMock(spec=AsyncHome) + hap.home.devices = [] + _set_diagnostic_defaults(hap.home) + + continue_refresh = asyncio.Event() + + async def block_refresh() -> None: + await continue_refresh.wait() + + hap.home.refresh_state_after_reconnect_async = AsyncMock(side_effect=block_refresh) + + with patch("homeassistant.components.homematicip_cloud.hap._LOGGER") as logger: + hap._ws_connection_closed.set() + hap._start_get_state_task() + first_task = hap._get_state_task + assert first_task is not None + await asyncio.sleep(0) + + hap._ws_connection_closed.set() + hap._start_get_state_task() + second_task = hap._get_state_task + assert second_task is not None + assert second_task is not first_task + await asyncio.sleep(0) + + continue_refresh.set() + await hass.async_block_till_done() + + assert first_task.cancelled() + logger.error.assert_not_called() + + +async def test_websocket_diagnostic_context_omits_none_values() -> None: + """None-valued diagnostics are omitted from the context string.""" + hap = HomematicipHAP(MagicMock(), MagicMock()) + hap.home = MagicMock() + hap.home.websocket_last_disconnect_reason = Mock(return_value=None) + hap.home.websocket_reconnect_attempt_count = Mock(return_value=2) + hap.home.websocket_seconds_since_last_message = Mock(return_value=None) + hap.home.websocket_message_count = Mock(return_value=10) + + context = hap._websocket_diagnostic_context() + + assert "last_disconnect_reason" not in context + assert "reconnect_attempts=2" in context + assert "message_count=10" in context + + +async def test_websocket_diagnostic_context_falls_back_when_all_unknown() -> None: + """Helper returns a non-empty fallback if every diagnostic is None.""" + hap = HomematicipHAP(MagicMock(), MagicMock()) + hap.home = MagicMock() + _set_diagnostic_defaults(hap.home) + + assert hap._websocket_diagnostic_context() == "no diagnostics available" + + +async def test_on_websocket_stale_logs_warning_then_error() -> None: + """Library callback maps severity to log level (warning vs error).""" + hap = HomematicipHAP(MagicMock(), MagicMock()) + hap.home = MagicMock() + _set_diagnostic_defaults(hap.home) + + with patch("homeassistant.components.homematicip_cloud.hap._LOGGER") as logger: + await hap._on_websocket_stale("warning", 400) + logger.warning.assert_called_once() + logger.error.assert_not_called() + + with patch("homeassistant.components.homematicip_cloud.hap._LOGGER") as logger: + await hap._on_websocket_stale("error", 1900) + logger.error.assert_called_once() + logger.warning.assert_not_called() + + +async def test_async_connect_registers_stale_handler() -> None: + """async_connect registers the library websocket-stale callback.""" + hap = HomematicipHAP(MagicMock(), MagicMock()) + home = MagicMock() + home.enable_events = AsyncMock() + home.set_on_websocket_stale_handler = MagicMock() + + await hap.async_connect(home) + + home.set_on_websocket_stale_handler.assert_called_once_with(hap._on_websocket_stale) + + +async def test_on_websocket_stale_log_format(caplog: pytest.LogCaptureFixture) -> None: + """Warning has the rounded seconds; diagnostic context is at debug level.""" + hap = HomematicipHAP(MagicMock(), MagicMock()) + hap.home = MagicMock() + _set_diagnostic_defaults(hap.home) + hap.home.websocket_message_count = Mock(return_value=42) + + with caplog.at_level("DEBUG"): + await hap._on_websocket_stale("warning", 423.7) + + assert "424" in caplog.text # %.0f rounds + assert "message_count=42" in caplog.text + + warning_records = [r for r in caplog.records if r.levelname == "WARNING"] + assert any("424" in r.getMessage() for r in warning_records) + assert not any("message_count" in r.getMessage() for r in warning_records) + + +async def test_get_state_clears_unreach_on_unchanged_devices() -> None: + """get_state must clear stale unreach flags after a reconnect. + + set_all_to_unavailable() sets unreach=True on all devices on disconnect; + get_current_state_async() only updates devices whose state actually + changed, so unchanged devices stay marked unreachable. We must clear it. + """ + hap = HomematicipHAP(MagicMock(), MagicMock()) + hap.home = MagicMock() + hap.home.get_current_state_async = AsyncMock() + device_changed = MagicMock(unreach=False) + device_unchanged = MagicMock(unreach=True) + hap.home.devices = [device_changed, device_unchanged] + + await hap.get_state() + + assert device_changed.unreach is False + assert device_unchanged.unreach is False