diff --git a/custom_components/localthings/coordinator.py b/custom_components/localthings/coordinator.py index 71f1dd4..db8ff6c 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: @@ -571,14 +579,44 @@ 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 DEFAULT_SETTLE_S's 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), and some writes settle + # on the device itself well after that: issue #9's washer packs + # cycle/detergent/softener selection into the same /course/vs/0 + # options[] array, and picking a new value there visibly needs a + # few seconds of internal validation/dispenser movement before the + # device's own state agrees -- while /washer/vs/0's temperature/ + # spin fields (plain flags, no device-side settling) confirm + # instantly on the same device. A short fixed window expired while + # the confirm poll was still in flight (or before the device had + # caught up internally), so that stale read landed unprotected and + # reverted the optimistic value, self-correcting again only once a + # later poll finally saw the real change -- read by the user as the + # write "reverting, then re-applying itself" a few seconds later. + # + # An earlier attempt at this also released the guard early, right + # after the confirming refresh completed, to avoid shutting out + # unrelated real updates (another automation, the physical remote) + # for the rest of settle_s. That was reverted: releasing the guard + # the moment one round trip finishes doesn't mean the device has + # actually caught up (exactly the slow-settling case above), and it + # introduced its own races around overlapping writes to the same + # href. Simpler and safer to just hold the guard for the full, + # generously-sized window and let it expire on its own. self._observe.apply(write_href, body, source='optimistic') - self._observe.mark_write_pending(write_href) + self._observe.mark_write_pending( + write_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", write_href, code) try: diff --git a/custom_components/localthings/manifest.json b/custom_components/localthings/manifest.json index 7e53305..889e8ef 100644 --- a/custom_components/localthings/manifest.json +++ b/custom_components/localthings/manifest.json @@ -12,5 +12,5 @@ "pyOpenSSL>=23.0", "smartthings-local>=0.1.0" ], - "version": "0.10.1" + "version": "0.11.0" } diff --git a/custom_components/localthings/observe.py b/custom_components/localthings/observe.py index e3c5aad..7d51109 100644 --- a/custom_components/localthings/observe.py +++ b/custom_components/localthings/observe.py @@ -115,8 +115,22 @@ class ObserveManager: could each read the same prior rep and the second writer would silently lose the first's fields, reintroducing the exact bug this merge fixes. + + `source == 'optimistic'` always bypasses the settle gate below, + even while this href is already settling from an earlier write. + Several independent selects can share one href -- issue #9's washer + packs cycle, detergent, and softener settings onto the same + /course/vs/0 -- so a second, different write to the same href + while the first's settle window is still open (up to + _POST_TIMEOUT_S + _POLL_TIMEOUT_S, tens of seconds -- see + coordinator.async_send_command) is an expected, normal sequence, + not a stale echo of the first write. Gating it the same as a + poll/sweep/observe update would silently drop the user's own + second selection from the cache until the first write's guard + happened to expire, i.e. the exact symptom this guard exists to + prevent, just relocated to whichever write loses the race. """ - if self._is_settling(href): + if source != 'optimistic' and self._is_settling(href): self.log.debug("dropping %s update for %s (settling)", source, href) return False with self._cache_lock: diff --git a/tests/localthings/test_coordinator.py b/tests/localthings/test_coordinator.py index ce4772d..a396815 100644 --- a/tests/localthings/test_coordinator.py +++ b/tests/localthings/test_coordinator.py @@ -749,6 +749,104 @@ async def test_climate_power_write_applies_to_its_own_href_not_bound_href( assert coordinator._observe._settle_until.get('/power/0') is not None +async def test_send_command_survives_stale_confirm_poll( + hass: HomeAssistant, mock_entry, mock_coordinator_observe_session, fridge_resources, +) -> None: + """The settle window must outlast the confirm poll async_send_command + triggers via async_request_refresh(), not just DEFAULT_SETTLE_S's fixed + few seconds (issue #9). Some devices settle a write internally slower + than that refresh's own round trip -- issue #9's washer packs cycle/ + detergent/softener selection into /course/vs/0's shared options[] + array, which visibly takes a few seconds of validation/dispenser + movement to catch up, unlike /washer/vs/0's plain temperature/spin + fields on the same device, which confirm instantly. A confirm poll that + lands before the device has caught up is stale, and a settle window + sized only to the fixed default (rather than the PUT+poll round trip) + expires before that poll even returns, so the stale read lands + unprotected and reverts the optimistic value -- self-correcting again + only once a later poll finally sees the real change. That reads to a + user as the write reverting, then reapplying itself, a few seconds + later.""" + from custom_components.localthings.registry.discovery import BoundEntity + from custom_components.localthings.registry.entities import NumberDesc + + fake = mock_coordinator_observe_session + await hass.config_entries.async_setup(mock_entry.entry_id) + await hass.async_block_till_done() + coordinator: LocalThingsCoordinator = hass.data[DOMAIN][mock_entry.entry_id] + + def _write_fn(payload, rep, href): + return (['test', 'vs', '0'], {'value': payload}) + + desc = NumberDesc(key='test', field='value', write_fn=_write_fn) + bound = BoundEntity(href='/test/vs/0', capability=coordinator.bound[0].capability, desc=desc) + + def _stale_confirm_poll(): + # Stand-in for the write's own confirming /device/0 poll racing + # against a stale read for the same href -- the device's internal + # state hasn't caught up to the write yet, even though it will a + # little later. + 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 and survived the stale + # confirm-poll race triggered by the refresh above. + assert coordinator._cache.get('/test/vs/0') == {'value': 5} + + # The settle window is still open afterward -- sized to outlast the + # whole PUT + confirm-poll round trip, not released the moment that + # round trip happens to finish. + applied = coordinator._observe.apply('/test/vs/0', {'value': 0}, source='observe') + assert applied is False + assert coordinator._cache.get('/test/vs/0') == {'value': 5} + + +async def test_second_write_to_same_href_lands_during_first_writes_settle_window( + hass: HomeAssistant, mock_entry, mock_coordinator_observe_session, +) -> None: + """Regression for issue #9: /course/vs/0 backs several independent + washer selects (cycle, detergent quantity, softener quantity, ...) + sharing one href. The settle window is now sized to tens of seconds + (see test_send_command_survives_stale_confirm_poll), which makes a + second, different write to that href landing while the first write's + window is still open a routine occurrence -- e.g. a user picking a + cycle and then adjusting detergent quantity within the same minute -- + not a rare edge case. The second write's own optimistic value must + still show up immediately; a guard meant to protect optimistic writes + from stale device echoes must not itself suppress a later one.""" + from custom_components.localthings.registry.discovery import BoundEntity + from custom_components.localthings.registry.entities import NumberDesc + + fake = mock_coordinator_observe_session + await hass.config_entries.async_setup(mock_entry.entry_id) + await hass.async_block_till_done() + coordinator: LocalThingsCoordinator = hass.data[DOMAIN][mock_entry.entry_id] + + desc_a = NumberDesc(key='cycle', field='cycle', + write_fn=lambda p, rep, href: (['test', 'vs', '0'], {'cycle': p})) + desc_b = NumberDesc(key='detergent', field='detergent', + write_fn=lambda p, rep, href: (['test', 'vs', '0'], {'detergent': p})) + bound_a = BoundEntity(href='/test/vs/0', capability=coordinator.bound[0].capability, desc=desc_a) + bound_b = BoundEntity(href='/test/vs/0', capability=coordinator.bound[0].capability, desc=desc_b) + + with patch.object(fake, 'subscribe'): + fake.post = lambda *a, **k: (0x44, b'') + await coordinator.async_send_command(bound_a, 'Eco') + assert coordinator._cache.get('/test/vs/0') == {'cycle': 'Eco'} + + # Still well within the first write's settle window. + await coordinator.async_send_command(bound_b, 'High') + + assert coordinator._cache.get('/test/vs/0') == {'cycle': 'Eco', 'detergent': 'High'} + + class TestRemoteControlEnabled: """remote_control_enabled (registry/capabilities/common.py) is the single source of truth for the /remotectrl on/off signal, shared by diff --git a/tests/localthings/test_observe.py b/tests/localthings/test_observe.py index 7d3fe9a..4ea057d 100644 --- a/tests/localthings/test_observe.py +++ b/tests/localthings/test_observe.py @@ -67,6 +67,30 @@ def test_apply_drops_update_during_settle_window(): assert mgr.cache.get('/oven/vs/0') == {'a': 1} +def test_apply_optimistic_bypasses_an_in_progress_settle_window(): + """Regression for issue #9: /course/vs/0 backs several independent + washer selects (cycle, detergent quantity, softener quantity, ...). + Picking a second one while the first's settle window is still open + (now sized to tens of seconds -- see coordinator._POST_TIMEOUT_S/ + _POLL_TIMEOUT_S) is a normal sequence, not a stale echo of the first + write, and must land in the cache immediately -- not get silently + dropped by a guard that exists to protect optimistic writes, not + suppress them.""" + mgr = _manager() + mgr.cache.apply_rep('/course/vs/0', {'Course': '1C', 'Detergent': '1'}, source='seed') + mgr.mark_write_pending('/course/vs/0', settle_s=30.0) + + result = mgr.apply('/course/vs/0', {'Detergent': '2'}, source='optimistic') + + assert result is True + assert mgr.cache.get('/course/vs/0') == {'Course': '1C', 'Detergent': '2'} + + # A poll/sweep/observe update racing in right behind it is still + # gated -- the second write's own guard (re-armed by mark_write_pending, + # not exercised directly here) is what protects it going forward. + assert mgr.apply('/course/vs/0', {'Detergent': '1'}, source='poll') is False + + def test_apply_accepts_update_after_settle_window_elapses(): mgr = _manager() mgr.mark_write_pending('/oven/vs/0', settle_s=0.05)