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..ffaa01cd 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,38 @@ 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 + # 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, + 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..71c5cd2e 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_is_non_fatal( 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 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. + 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.INFO): + 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_is_non_fatal( + uc_fallback_lock: ZWaveJSLock, + mock_uc_utils: dict, + caplog: pytest.LogCaptureFixture, +) -> None: + """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 + 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.INFO): + 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" )