Merge pull request #60 from mbillow/claude/issue-9-optimistic-write-debug-k4fjdb

fix: settle-window fixes for slow-settling, shared-href writes (issue #9)

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:

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"
 }

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:

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

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)