homematicip_cloud: harden post-reconnect state recovery using 2.9.0 diagnostics (#169526)

This commit is contained in:
Christian Lackas
2026-06-15 16:08:40 +02:00
committed by GitHub
parent 27573c5231
commit 09a72ac505
4 changed files with 353 additions and 114 deletions
@@ -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),
}
@@ -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()
@@ -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,
}),
})
# ---
+221 -58
View File
@@ -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