Stop reconnecting a session a dark appliance never opened

A switched-off washer or dryer fails in the DTLS handshake, not in a
poll: `_poll_once` opens the session itself, so `_connect_session` runs
to its 12s timeout with nothing to show. The poll path treated that like
any other poll failure and ran its reconnect -- close the session, pause,
poll again -- but there is no session to close and no association for the
device to clean up, so the retry was the identical handshake five seconds
later. That cost 29s of every 30s interval, and the same again on every
setup attempt for an entry with no snapshot to load from.

`_poll_once` now records which of the two failed, and the poll path skips
the retry when the handshake is what never completed. A session that
opened and then broke still reconnects within the cycle.

The log was the half the reporters saw: an ERROR every cycle (plus a
WARNING once three "reconnects" piled up) for a state this integration is
built to sit through, which issue #269's reporter read as the integration
having failed. An outage now reports once, DEBUG for the cycles after it,
and INFO when the device answers again.

Fixes #269

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)
+                    return self._device_unreachable("poll failed after reconnect", 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
                 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

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.

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