diff --git a/custom_components/localthings/coordinator.py b/custom_components/localthings/coordinator.py index 83b2d4b..64f02bc 100644 --- a/custom_components/localthings/coordinator.py +++ b/custom_components/localthings/coordinator.py @@ -77,6 +77,14 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): # fine session shouldn't tear down a working OBSERVE subscription. _POLL_TIMEOUT_LIMIT: int = 3 + # Timeouts for the two network round trips a write triggers: the PUT + # itself (_do_put), then the confirming full /device/0 summary poll + # async_send_command requests right after (_poll_once). Named here + # (rather than left as inline literals) so the write-settle window + # below can be sized to always outlast both — see async_send_command. + _POST_TIMEOUT_S: float = 8.0 + _POLL_TIMEOUT_S: float = 35.0 + def __init__(self, hass: HomeAssistant, entry: ConfigEntry) -> None: # Per-device logger (module logger scoped to this device's host) so # every log line — including the base DataUpdateCoordinator's own @@ -211,7 +219,7 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): # would have succeeded, not a dead session. 35s gives a slow # blockwise transfer room to actually finish instead of # generating a TimeoutError every cycle. - code, payload = sess.get(_SEED_PATH, timeout=35.0) + code, payload = sess.get(_SEED_PATH, timeout=self._POLL_TIMEOUT_S) except TimeoutError: raise except Exception as e: @@ -555,19 +563,43 @@ class LocalThingsCoordinator(DataUpdateCoordinator[dict[str, Any]]): # onto, the settle window was just delaying the real device # confirmation for a few seconds on every write, which read exactly # like the write being silently reverted (issue #27). + # + # settle_s must outlast the PUT and the async_request_refresh() + # below combined, not just a fixed few seconds -- that refresh is a + # full /device/0 summary poll, which _POLL_TIMEOUT_S itself admits + # can legitimately take tens of seconds on these devices (see + # _poll_once). A shorter window expires while that confirm poll is + # still in flight, so its result -- stale, if the device's own + # resource tree hadn't caught up to the instant physical change + # yet -- lands unprotected and reverts the optimistic value, with + # nothing to correct it again until the next scheduled summary poll + # up to SUMMARY_INTERVAL_S later. That's the 20-60s lag reported in + # issues #17/#53 even after the optimistic-apply fix above. self._observe.apply(href, body, source='optimistic') - self._observe.mark_write_pending(href) + self._observe.mark_write_pending( + href, settle_s=self._POST_TIMEOUT_S + self._POLL_TIMEOUT_S + ) def _do_put(): sess = self._session if sess is None: raise RuntimeError("no session") - code, _ = sess.post(path_segs, cbor2.dumps(body), timeout=8.0) + code, _ = sess.post(path_segs, cbor2.dumps(body), timeout=self._POST_TIMEOUT_S) self._log.info("PUT %s → code %#04x", href, code) try: await self.hass.async_add_executor_job(_do_put) except Exception as e: self._log.error("command failed for %s: %s", href, e) + # The write's own confirmation never happened, so don't hold + # the (possibly wrong) optimistic value hostage against real + # updates for the rest of the long settle window above. + self._observe.clear_write_pending(href) else: await self.async_request_refresh() + # The confirming refresh has now run and applied its result + # (subject to the settle guard above), so this write's own + # round trip is done -- release the guard rather than leaving + # real subsequent updates (another automation, the physical + # remote) shut out for whatever's left of settle_s. + self._observe.clear_write_pending(href) diff --git a/custom_components/localthings/observe.py b/custom_components/localthings/observe.py index e3c5aad..a9d1219 100644 --- a/custom_components/localthings/observe.py +++ b/custom_components/localthings/observe.py @@ -82,6 +82,22 @@ class ObserveManager: with self._settle_lock: self._settle_until[href] = time.monotonic() + settle_s + def clear_write_pending(self, href: str) -> None: + """End a write's settle window early, once its own confirming + refresh has actually completed (see coordinator.async_send_command). + + mark_write_pending's caller sizes settle_s to safely outlast that + confirm round trip so the guard can't lapse mid-flight (see issues + #17/#53) -- but that same generous duration would needlessly hold + the cache hostage against real, unrelated updates (another + automation, the physical remote) for the rest of the window once + the round trip is already done. Called from both the success and + failure paths of a write, so a failed write doesn't leave a wrong + optimistic value shielded from correction for the full window either. + """ + with self._settle_lock: + self._settle_until.pop(href, None) + def _is_settling(self, href: str) -> bool: with self._settle_lock: until = self._settle_until.get(href) diff --git a/tests/localthings/test_coordinator.py b/tests/localthings/test_coordinator.py index 4692e9b..32f20c5 100644 --- a/tests/localthings/test_coordinator.py +++ b/tests/localthings/test_coordinator.py @@ -643,7 +643,11 @@ async def test_write_marks_href_pending_before_post( hass: HomeAssistant, mock_entry, mock_coordinator_observe_session ) -> None: """async_send_command must call mark_write_pending before POSTing so a - slow-to-settle device can't immediately revert the optimistic write.""" + slow-to-settle device can't immediately revert the optimistic write -- + and the window must still be open through the POST itself (checked from + inside the fake POST, since the guard is released once the write's own + confirming refresh completes -- see + test_send_command_applies_write_optimistically_before_settling).""" from custom_components.localthings.registry.discovery import BoundEntity from custom_components.localthings.registry.entities import NumberDesc @@ -658,21 +662,39 @@ async def test_write_marks_href_pending_before_post( desc = NumberDesc(key='test', field='value', write_fn=_write_fn) bound = BoundEntity(href='/test/vs/0', capability=coordinator.bound[0].capability, desc=desc) + settling_during_post = None + + def _post(*a, **k): + nonlocal settling_during_post + settling_during_post = coordinator._observe._settle_until.get('/test/vs/0') is not None + return (0x44, b'') + with patch.object(fake, 'subscribe'): - fake.post = lambda *a, **k: (0x44, b'') + fake.post = _post await coordinator.async_send_command(bound, 5) - assert coordinator._observe._settle_until.get('/test/vs/0') is not None + assert settling_during_post is True + # Released once the write's own confirming refresh has completed, not + # left open for the rest of what is now a much longer settle window. + assert coordinator._observe._settle_until.get('/test/vs/0') is None async def test_send_command_applies_write_optimistically_before_settling( - hass: HomeAssistant, mock_entry, mock_coordinator_observe_session + hass: HomeAssistant, mock_entry, mock_coordinator_observe_session, fridge_resources, ) -> None: """The cache must reflect a write immediately, and stay put against a stale echo for the rest of the settle window -- otherwise mark_write_pending has nothing to protect and just delays the real device confirmation instead, which reads to a user as the write being - silently reverted (issue #27).""" + silently reverted (issue #27). + + The settle window now spans the whole POST + confirming-refresh round + trip async_send_command awaits (see coordinator._POST_TIMEOUT_S / + _POLL_TIMEOUT_S), not a fixed few seconds -- so this drives the stale + echo through _poll_once itself, racing in while that confirming refresh + is still in flight (issues #17/#53: a full summary poll on these + devices can legitimately take far longer than a short fixed window, + which let a stale read land unprotected and revert the write).""" from custom_components.localthings.registry.discovery import BoundEntity from custom_components.localthings.registry.entities import NumberDesc @@ -687,20 +709,29 @@ async def test_send_command_applies_write_optimistically_before_settling( desc = NumberDesc(key='test', field='value', write_fn=_write_fn) bound = BoundEntity(href='/test/vs/0', capability=coordinator.bound[0].capability, desc=desc) - with patch.object(fake, 'subscribe'): + def _stale_confirm_poll(): + # Stand-in for the write's own confirming /device/0 poll racing + # against an independent stale update for the same href (e.g. the + # device's resource tree hadn't caught up internally yet, even + # though the physical change was instant). + coordinator._observe.apply('/test/vs/0', {'value': 0}, source='poll') + return fridge_resources + + with ( + patch.object(fake, 'subscribe'), + patch.object(LocalThingsCoordinator, '_poll_once', side_effect=_stale_confirm_poll), + ): fake.post = lambda *a, **k: (0x44, b'') await coordinator.async_send_command(bound, 5) # The optimistic value is visible right away, without waiting for a - # device response. + # device response, and survived the stale confirm-poll race above. assert coordinator._cache.get('/test/vs/0') == {'value': 5} - # A stale update racing in behind the write (e.g. a poll/notify that - # was already in flight before the PUT) must not clobber it while the - # settle window is open. + # The write's own round trip is done, so the guard has been released -- + # a later, genuinely new update is no longer held back. applied = coordinator._observe.apply('/test/vs/0', {'value': 0}, source='observe') - assert applied is False - assert coordinator._cache.get('/test/vs/0') == {'value': 5} + assert applied is True class TestRemoteControlEnabled: @@ -803,7 +834,7 @@ async def test_send_command_allowed_when_remote_control_enabled( fake.post = lambda *a, **k: (0x44, b'') await coordinator.async_send_command(bound, 5) - assert coordinator._observe._settle_until.get('/test/vs/0') is not None + assert coordinator._cache.get('/test/vs/0') == {'value': 5} async def test_send_command_remote_control_check_precedes_validate_fn(