From 5e1cbc5b5272e558cd52f1588be556e49e89b4c5 Mon Sep 17 00:00:00 2001 From: raman325 <7243222+raman325@users.noreply.github.com> Date: Fri, 12 Jun 2026 23:19:04 -0400 Subject: [PATCH 1/2] fix(zwave_js): make UC v1 post-write verify failures non-fatal (#1251) The post-set/clear verification GET that forces V1 locks' value cache to refresh was raising LockDisconnected on any Z-Wave error, which on Schlage UC v1 locks with flaky interviews (the canonical #1251 case) turned every credential write into a slot-suspension feedback loop: the SET ack'd at the wire, the verify GET timed out the same way the interview did, and the whole operation reported failure -- the sync manager then retried, hit the same timeout, and eventually disabled the slot. Log the verify timeout and continue: the SET/CLEAR already ack'd and the caller's `_push_credential_update` delivers the truth to the coordinator immediately afterward, so the optimistic push is the safety net. The hourly hard-refresh backstop reconciles any genuine cache drift. Non-Z-Wave exceptions (programming bugs) still propagate. Co-Authored-By: Claude Opus 4.7 (1M context) Entire-Checkpoint: 49038c7ae9a3 --- .../providers/_zwave_js_uc.py | 30 +++++--- tests/providers/zwave_js/test_uc_fallback.py | 72 +++++++++++++++++-- 2 files changed, 88 insertions(+), 14 deletions(-) diff --git a/custom_components/lock_code_manager/providers/_zwave_js_uc.py b/custom_components/lock_code_manager/providers/_zwave_js_uc.py index 8bcf2d9d..03af25db 100644 --- a/custom_components/lock_code_manager/providers/_zwave_js_uc.py +++ b/custom_components/lock_code_manager/providers/_zwave_js_uc.py @@ -395,20 +395,34 @@ async def _async_uc_verify_write( Force-update the value cache after a set/clear on a V1 lock. V1 locks don't reliably update the Z-Wave JS value cache after a - write. Poll the slot directly from the device to force-update the - cache before the coordinator reads it, preventing sync loops. - Wrap failures as LockDisconnected so they route to the retry path - instead of suspending the slot. + write; this poll fires a CC GET directly at the node to force + the value DB to refresh before the next coordinator read. + + When the GET itself fails (the canonical case being a Schlage + UC v1 lock whose interview also times out -- issue #1251), log + and continue: the SET/CLEAR already ack'd at the wire and the + caller immediately emits ``_push_credential_update`` with the + true post-write state, so the coordinator already has the + truth. Failing the whole operation here turns a flaky lock into + a slot-suspension feedback loop -- the exact pathology the + fallback is meant to dodge. The hourly hard-refresh backstop + reconciles any genuine cache drift. + + Non-Z-Wave exceptions (programming bugs) still propagate. """ if self._usercode_cc_version >= 2: return try: await get_usercode_from_node(self.node, code_slot) except BaseZwaveJSServerError as err: - raise LockDisconnected( - f"Post-{operation} verification poll failed for " - f"{self.lock.entity_id} slot {code_slot}: {err}" - ) from err + _LOGGER.warning( + "Lock %s slot %s: post-%s verification poll failed (%s); " + "trusting optimistic push and continuing", + self.lock.entity_id, + code_slot, + operation, + err, + ) def _uc_code_slot_in_use(self, code_slot: int) -> bool | None: """Return whether a User Code CC slot is in use, None when unknown.""" diff --git a/tests/providers/zwave_js/test_uc_fallback.py b/tests/providers/zwave_js/test_uc_fallback.py index e97067de..31962dbf 100644 --- a/tests/providers/zwave_js/test_uc_fallback.py +++ b/tests/providers/zwave_js/test_uc_fallback.py @@ -10,6 +10,7 @@ from __future__ import annotations +import logging from unittest.mock import AsyncMock, MagicMock, PropertyMock, patch import pytest @@ -995,23 +996,82 @@ async def test_uc_clear_credential_failure_status_raises_operation_failed( await uc_fallback_lock.async_delete_credential(ref) -async def test_uc_v1_verify_poll_failure_raises_lock_disconnected( +async def test_uc_v1_set_verify_failure_logs_warning_and_continues( uc_fallback_lock: ZWaveJSLock, mock_uc_utils: dict, + caplog: pytest.LogCaptureFixture, ) -> None: - """A failing post-write verification poll maps to LockDisconnected. - - The write itself succeeded, so routing to the retry path (rather - than suspending the slot) lets the next tick verify the result. + """V1 verify failure during set is logged but does not fail the set. + + The wire-level SET already ack'd and the optimistic + ``_push_credential_update`` delivers the truth to the coordinator. + Failing here turns a flaky-interview lock (issue #1251) into a + slot-suspension feedback loop -- the exact pathology the fallback + is meant to dodge. The hourly hard-refresh backstop reconciles any + cache drift that genuinely matters. """ + mock_coordinator = MagicMock() + mock_coordinator.data = {} + uc_fallback_lock.coordinator = mock_coordinator + + mock_uc_utils["get_usercode_from_node"].side_effect = FailedZWaveCommand( + "cmd", 1, "node gone" + ) + + credential = Credential( + type=CredentialType.PIN, slot=5, state=SlotCredential.known("4321") + ) + with caplog.at_level(logging.WARNING): + result = await uc_fallback_lock.async_set_credential( + user_id=5, credential=credential, pin="4321", name=None, source="sync" + ) + + assert result is True + mock_coordinator.push_update.assert_called_once_with( + {5: SlotCredential.known("4321")} + ) + assert "verification poll failed" in caplog.text + + +async def test_uc_v1_clear_verify_failure_logs_warning_and_continues( + uc_fallback_lock: ZWaveJSLock, + mock_uc_utils: dict, + caplog: pytest.LogCaptureFixture, +) -> None: + """V1 verify failure during clear is non-fatal too; mirrors the set path.""" + mock_coordinator = MagicMock() + mock_coordinator.data = {} + uc_fallback_lock.coordinator = mock_coordinator + mock_uc_utils["get_usercode_from_node"].side_effect = FailedZWaveCommand( "cmd", 1, "node gone" ) + ref = CredentialRef(user_id=3, type=CredentialType.PIN, slot=3) + with caplog.at_level(logging.WARNING): + result = await uc_fallback_lock.async_delete_credential(ref) + + assert result is True + mock_coordinator.push_update.assert_called_once_with({3: SlotCredential.empty()}) + assert "verification poll failed" in caplog.text + + +async def test_uc_v1_verify_non_zwave_error_propagates( + uc_fallback_lock: ZWaveJSLock, + mock_uc_utils: dict, +) -> None: + """Non-Z-Wave verify errors still propagate as bugs. + + The softening only covers ``BaseZwaveJSServerError``; a RuntimeError + here means a programming bug and must surface for diagnosis rather + than be silently swallowed alongside the wire-level timeouts. + """ + mock_uc_utils["get_usercode_from_node"].side_effect = RuntimeError("bug") + credential = Credential( type=CredentialType.PIN, slot=5, state=SlotCredential.known("4321") ) - with pytest.raises(LockDisconnected, match="verification poll failed"): + with pytest.raises(RuntimeError, match="bug"): await uc_fallback_lock.async_set_credential( user_id=5, credential=credential, pin="4321", name=None, source="sync" ) From 32de8e31cecaf1051a7d724280cca91e58575d96 Mon Sep 17 00:00:00 2001 From: raman325 <7243222+raman325@users.noreply.github.com> Date: Fri, 12 Jun 2026 23:23:08 -0400 Subject: [PATCH 2/2] fix(zwave_js): log UC v1 verify failures at INFO, not WARNING The verify-failure path fires on every write to an affected lock; the per-lock fallback activation already emits a one-shot WARNING that flags the underlying #1251 pathology, so the per-write follow-on should not escalate to WARNING and spam the log. Co-Authored-By: Claude Opus 4.7 (1M context) Entire-Checkpoint: 793557c7d881 --- .../lock_code_manager/providers/_zwave_js_uc.py | 6 +++++- tests/providers/zwave_js/test_uc_fallback.py | 12 ++++++------ 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/custom_components/lock_code_manager/providers/_zwave_js_uc.py b/custom_components/lock_code_manager/providers/_zwave_js_uc.py index 03af25db..ffaa01cd 100644 --- a/custom_components/lock_code_manager/providers/_zwave_js_uc.py +++ b/custom_components/lock_code_manager/providers/_zwave_js_uc.py @@ -415,7 +415,11 @@ async def _async_uc_verify_write( try: await get_usercode_from_node(self.node, code_slot) except BaseZwaveJSServerError as err: - _LOGGER.warning( + # INFO, not WARNING: the per-lock fallback activation already + # logs a one-shot WARNING; verify timeouts on a flagged lock + # are the predicted consequence of the same interview + # pathology and would spam at WARNING level on every write. + _LOGGER.info( "Lock %s slot %s: post-%s verification poll failed (%s); " "trusting optimistic push and continuing", self.lock.entity_id, diff --git a/tests/providers/zwave_js/test_uc_fallback.py b/tests/providers/zwave_js/test_uc_fallback.py index 31962dbf..71c5cd2e 100644 --- a/tests/providers/zwave_js/test_uc_fallback.py +++ b/tests/providers/zwave_js/test_uc_fallback.py @@ -996,12 +996,12 @@ async def test_uc_clear_credential_failure_status_raises_operation_failed( await uc_fallback_lock.async_delete_credential(ref) -async def test_uc_v1_set_verify_failure_logs_warning_and_continues( +async def test_uc_v1_set_verify_failure_is_non_fatal( uc_fallback_lock: ZWaveJSLock, mock_uc_utils: dict, caplog: pytest.LogCaptureFixture, ) -> None: - """V1 verify failure during set is logged but does not fail the set. + """V1 verify failure during set is logged at INFO and does not fail the set. The wire-level SET already ack'd and the optimistic ``_push_credential_update`` delivers the truth to the coordinator. @@ -1021,7 +1021,7 @@ async def test_uc_v1_set_verify_failure_logs_warning_and_continues( credential = Credential( type=CredentialType.PIN, slot=5, state=SlotCredential.known("4321") ) - with caplog.at_level(logging.WARNING): + with caplog.at_level(logging.INFO): result = await uc_fallback_lock.async_set_credential( user_id=5, credential=credential, pin="4321", name=None, source="sync" ) @@ -1033,12 +1033,12 @@ async def test_uc_v1_set_verify_failure_logs_warning_and_continues( assert "verification poll failed" in caplog.text -async def test_uc_v1_clear_verify_failure_logs_warning_and_continues( +async def test_uc_v1_clear_verify_failure_is_non_fatal( uc_fallback_lock: ZWaveJSLock, mock_uc_utils: dict, caplog: pytest.LogCaptureFixture, ) -> None: - """V1 verify failure during clear is non-fatal too; mirrors the set path.""" + """V1 verify failure during clear is logged at INFO and does not fail the clear.""" mock_coordinator = MagicMock() mock_coordinator.data = {} uc_fallback_lock.coordinator = mock_coordinator @@ -1048,7 +1048,7 @@ async def test_uc_v1_clear_verify_failure_logs_warning_and_continues( ) ref = CredentialRef(user_id=3, type=CredentialType.PIN, slot=3) - with caplog.at_level(logging.WARNING): + with caplog.at_level(logging.INFO): result = await uc_fallback_lock.async_delete_credential(ref) assert result is True