mark_write_pending's window was a fixed few seconds, started before the PUT and the confirming /device/0 refresh that follows it -- but that refresh is a full summary poll, which can legitimately take far longer than that on these AC devices. The window routinely expired while the confirm poll was still in flight, so a stale read (the device's own resource tree hadn't caught up to the instant physical change yet) landed unprotected and reverted the optimistic write, with nothing to correct it again until the next scheduled summary poll. That's the 20-60s lag both issues report even after the earlier optimistic-apply fix. Size the window to cover the PUT and confirm-poll timeouts combined, and release it as soon as that round trip actually completes (success or failure) instead of leaving it open for the rest of a now much longer window.
This commit is contained in:
@@ -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)
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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(
|
||||
|
||||
Reference in New Issue
Block a user