bhetherman/localthings
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge pull request #402 from mbillow/claude/offline-device-startup-64bjpt

Browse Source 
Stop reconnecting a session a dark appliance never opened
This commit is contained in:
Marc Billow
2026-08-19 07:27:06 -05:00
committed by GitHub
parent 66b4f1400b 5ab0c9b5a8
commit 61d2b9e9ff
3 changed files with 197 additions and 21 deletions
Download Patch File Download Diff File Expand all files Collapse all files
custom_components/localthings/coordinator.py
+65 -18
View File
@@ -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
docs/investigations/offline-setup.md
+26
View File
@@ -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
+106 -3
View File
@@ -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()