diff --git a/custom_components/localthings/coordinator.py b/custom_components/localthings/coordinator.py index a7da859..37625a3 100644 --- a/custom_components/localthings/coordinator.py +++ b/custom_components/localthings/coordinator.py @@ -337,6 +337,13 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): self.device_type_name: str | None = None self.one_ui_version: str = "" self._consecutive_poll_timeouts = 0 + # Set by _poll_once when the failure was the DTLS handshake itself. + # A switched-off appliance fails there every cycle, and there is no + # session to tear down and re-establish -- see _async_update_data. + self._handshake_failed = False + # Consecutive cycles that ended with no data from the device, so an + # outage is reported once rather than once per poll (issue #269). + self._failed_cycles = 0 self._unbound_hrefs: list[str] = [] self._reconnect_times: list[float] = [] # See _maybe_retry_observe_mode: last_mode_change_ts alone doesn't @@ -861,9 +868,18 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): call's own timeout and surfacing as an ambiguous `TimeoutError`. See `_defer_reconnect_for` for what that changes about how soon a confirmed-dead session gets reconnected. + + Sets `_handshake_failed` so `_async_update_data` can tell a broken + session from one that never opened -- a switched-off appliance fails + in `_connect_session` every cycle, with nothing to reconnect. """ if self._session is None: - self._connect_session() + try: + self._connect_session() + except Exception: + self._handshake_failed = True + raise + self._handshake_failed = False sess = self._session assert sess is not None try: @@ -1665,6 +1681,42 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): self._reconnect_times.append(now) return len(self._reconnect_times) >= self._RECONNECT_WARN_THRESHOLD + def _mark_device_answered(self) -> None: + """Clear the bookkeeping a poll getting through invalidates.""" + self._consecutive_poll_timeouts = 0 + if self._failed_cycles: + self._log.info("device answered again after %d failed cycles", self._failed_cycles) + self._failed_cycles = 0 + + def _device_unreachable(self, what: str, e: Exception) -> dict[str, Any]: + """End a cycle that got no data, either degraded or as a failure. + + Reported once per outage rather than once per cycle: an appliance + that is switched off fails identically every 30s for as long as it + stays off (issue #269), and this integration is built to sit through + exactly that (issue #295). Home Assistant logs the transition into + and out of a failed update on its own. + + Raises `UpdateFailed` unless there are bound entities and cached + state to carry the last-known values on -- same precondition as + `_defer_reconnect_for` (issue #254). + """ + self._failed_cycles += 1 + if self._failed_cycles == 1: + self._log.error("%s: %s", what, e) + else: + self._log.debug("%s (%d cycles): %s", what, self._failed_cycles, e) + # Without this, a fully unreachable device left the connection-mode + # sensor stuck on "Push" forever -- only a successful poll ever + # downgraded it (issue #287). No just_downgraded_from_observe here: + # there's no live session this cycle to resubscribe on. + if self._observe.mode == MODE_OBSERVE: + self._observe.downgrade_to_poll() + if self._discovered and self._cache.snapshot(): + self._log.debug("Full error:", exc_info=e) + return flatten(self.bound, self.entity_resources()) + raise UpdateFailed(f"{what}: {e}") from e + # ------------------------------------------------------------------ # DataUpdateCoordinator hook # ------------------------------------------------------------------ @@ -1678,7 +1730,7 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): async with self._session_lock: try: resources = await self.hass.async_add_executor_job(self._poll_once) - self._consecutive_poll_timeouts = 0 + self._mark_device_answered() except Exception as e: if self._defer_reconnect_for(e): self._log.debug( @@ -1689,6 +1741,15 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): ) return flatten(self.bound, self.entity_resources()) self._consecutive_poll_timeouts = 0 + if self._handshake_failed: + # The handshake never completed, so there is no session + # to close and no association for the device to clean + # up: reconnecting would just repeat the same doomed + # handshake five seconds later. That doubled what a + # switched-off appliance costs -- two handshake timeouts + # per cycle, and the same wait again on every setup + # attempt while it stays dark (issue #269). + return self._device_unreachable("device unreachable", e) # A lone reconnect is routine (README's "Known device # behavior"); only warn once they pile up. Pause first so # the device can clean up its DTLS state before we knock @@ -1702,23 +1763,9 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): try: resources = await self.hass.async_add_executor_job(self._poll_once) except Exception as e2: - self._log.error("poll failed after reconnect: %s", e2) - # Without this, a fully unreachable device left the - # connection-mode sensor stuck on "Push" forever -- only - # the success branch below ever downgraded it (issue - # #287). No just_downgraded_from_observe here: there's no - # live session this cycle to resubscribe on. - if self._observe.mode == MODE_OBSERVE: - self._observe.downgrade_to_poll() - snapshot = self._cache.snapshot() - # Same precondition as _defer_reconnect_for (issue #254): - # degraded-but-successful data only makes sense once - # there are bound entities to carry it. - if self._discovered and snapshot: - self._log.debug("Full error:", exc_info=e2) - return flatten(self.bound, self.entity_resources()) - raise UpdateFailed(f"poll failed after reconnect: {e2}") from e2 + return self._device_unreachable("poll failed after reconnect", e2) else: + self._mark_device_answered() # A fresh session has zero OBSERVE registrations; if we # were in observe mode that state is now stale. Tear it # down and resubscribe immediately below instead of diff --git a/docs/investigations/offline-setup.md b/docs/investigations/offline-setup.md index 7ff350f..f085638 100644 --- a/docs/investigations/offline-setup.md +++ b/docs/investigations/offline-setup.md @@ -152,6 +152,32 @@ is keyed on `(domain, issue_id)`, `dataclasses.replace` in reloads non-persistent issues with their dismissal intact, so one row per entry survives restarts and an "Ignore" sticks. +### What a cycle costs while the appliance stays dark (issue #269) + +An appliance switched off at the wall isn't a one-cycle blip: it fails the +same way every 30s for hours, and both halves of that failure were being paid +twice. + +`_poll_once` opens the session itself when there isn't one, so a switched-off +appliance fails *in the handshake* — 12s (`DtlsCoapSession.HANDSHAKE_TIMEOUT_S`) +with nothing to show for it. The poll path then treated that like any other +poll failure and ran its reconnect: close the session, pause +`_RECONNECT_PAUSE_S`, poll again. There is no session to close and no +association for the device to clean up, so the "reconnect" was the identical +handshake five seconds later — 29s of the 30s interval spent proving the +appliance is off, twice over, and the same again on every `SETUP_RETRY` +attempt for an entry with no snapshot to load from. `_handshake_failed` marks +that case in `_poll_once` so the poll path can skip the retry; a session that +opened and *then* broke still reconnects within the cycle. + +The log was the half the reporters actually saw: `poll failed after +reconnect` at ERROR every cycle, plus a `reconnect_is_frequent` WARNING once +three piled up, for a state this integration is specifically built to sit +through. Issue #269's reporter read that repetition as the integration having +failed. It's one ERROR per outage now, DEBUG for the cycles after it, and one +INFO when the device answers again — HA's own coordinator already logs the +transition into and out of a failed update. + ## What this still won't do Entities will be present and `unavailable` — not showing their last values. diff --git a/tests/localthings/test_offline_setup.py b/tests/localthings/test_offline_setup.py index dc9597f..b3b3f5a 100644 --- a/tests/localthings/test_offline_setup.py +++ b/tests/localthings/test_offline_setup.py @@ -2,15 +2,18 @@ The device's entity set only exists as the output of a live poll, so coming up offline means replaying the last successful discovery from a stored -snapshot. These tests pin the four things that makes load-bearing: the +snapshot. These tests pin the five things that makes load-bearing: the snapshot gets written, it produces the same entity set offline, the -coordinator keeps polling until the device answers, and a live discovery that +coordinator keeps polling until the device answers, a live discovery that disagrees with the snapshot reloads the entry rather than silently keeping a -stale set. +stale set, and each of those retries costs one handshake and one log line +rather than repeating both every cycle (issue #269). """ from __future__ import annotations +import logging +import time from contextlib import contextmanager from datetime import timedelta from unittest.mock import patch @@ -19,8 +22,10 @@ import pytest from homeassistant.config_entries import ConfigEntryState from homeassistant.core import HomeAssistant from homeassistant.helpers import issue_registry as ir +from homeassistant.helpers.update_coordinator import UpdateFailed from homeassistant.util import dt as dt_util from pytest_homeassistant_custom_component.common import async_fire_time_changed +from smartthings_local.errors import SessionTimeoutError from custom_components.localthings.const import DOMAIN, SUMMARY_INTERVAL_S from custom_components.localthings.coordinator import LocalThingsCoordinator @@ -29,6 +34,7 @@ from custom_components.localthings.registry.identity import DeviceIdentity from .conftest import _load_fridge_resources as _load_fridge _COORD = "custom_components.localthings.coordinator.LocalThingsCoordinator" +_COORD_LOGGER = "custom_components.localthings.coordinator" @contextmanager @@ -58,6 +64,20 @@ def _unreachable(): yield +@contextmanager +def _dark(handshakes: list[float]): + """A switched-off appliance: the DTLS handshake itself times out, which + is what `_poll_once` really hits -- `_unreachable` above stands in one + step later, after a session it never gets. Records every attempt.""" + + def _connect(self) -> None: + handshakes.append(time.monotonic()) + raise SessionTimeoutError() + + with patch(f"{_COORD}._connect_session", _connect), patch(f"{_COORD}._close_session"): + yield + + def _store_key(entry) -> str: return f"{DOMAIN}.{entry.entry_id}.discovery" @@ -416,3 +436,86 @@ async def test_offline_load_survives_repeated_poll_failures( coordinator: LocalThingsCoordinator = hass.data[DOMAIN][mock_entry.entry_id] assert coordinator.last_update_success + + +# --------------------------------------------------------------------------- +# What a cycle against a dark appliance costs (issue #269) +# --------------------------------------------------------------------------- + + +async def test_dark_appliance_costs_one_handshake_per_cycle( + hass: HomeAssistant, mock_entry +) -> None: + """A washer or dryer is switched off most of the day, so every one of + these cycles is paid for real: a handshake against a device that isn't + there runs to its full 12s timeout, and the reconnect retry used to add a + second one plus its pause to every cycle -- and to every setup attempt + while the appliance stayed dark. There is no session to reconnect when + the handshake is what failed, so the retry only repeated it.""" + resources = _load_fridge() + await _setup_online_then_unload(hass, mock_entry, resources) + + handshakes: list[float] = [] + with _dark(handshakes): + await hass.config_entries.async_setup(mock_entry.entry_id) + await hass.async_block_till_done() + assert len(handshakes) == 1 + + for expected in (2, 3, 4): + await _tick(hass) + assert len(handshakes) == expected + + +async def test_dark_appliance_reports_its_outage_once( + hass: HomeAssistant, mock_entry, caplog +) -> None: + """Sitting through an outage is what this integration is built to do + (issue #295), so it must not log an error every 30s for as long as the + appliance is off -- the reporter on issue #269 read exactly that repeated + line as the integration having failed. One line per outage, and one when + the device comes back.""" + resources = _load_fridge() + await _setup_online_then_unload(hass, mock_entry, resources) + + caplog.clear() + caplog.set_level(logging.INFO) + with _dark([]): + await hass.config_entries.async_setup(mock_entry.entry_id) + await hass.async_block_till_done() + for _ in range(3): + await _tick(hass) + + ours = [r for r in caplog.records if r.name.startswith(f"{_COORD_LOGGER}.")] + errors = [r for r in ours if r.levelno >= logging.ERROR] + assert len(errors) == 1 + assert "device unreachable" in errors[0].getMessage() + + with _reachable(resources): + await _tick(hass) + + recovered = [r for r in caplog.records if "device answered again" in r.getMessage()] + assert len(recovered) == 1 + assert recovered[0].levelno == logging.INFO + + +async def test_broken_session_still_reconnects_within_the_cycle( + hass: HomeAssistant, mock_entry +) -> None: + """The counterpart guard: skipping the reconnect is only right when the + handshake never completed. A session that opened and then failed mid-poll + still gets torn down and re-established without waiting a whole cycle.""" + coordinator = LocalThingsCoordinator(hass, mock_entry) + coordinator._discovered = True + + with ( + patch.object( + LocalThingsCoordinator, "_poll_once", side_effect=RuntimeError("poll GET failed") + ) as poll, + patch.object(LocalThingsCoordinator, "_close_session") as close, + patch("custom_components.localthings.coordinator.asyncio.sleep"), + pytest.raises(UpdateFailed), + ): + await coordinator._async_update_data() + + assert poll.call_count == 2 + close.assert_called_once()