Allow delayed duplicate responses (#244)

* Demote duplicate or delayed response to debug, not warning

* Log the waiting response queue

* Delay `MismatchedResponseError` in case the firmware eventually responds

* Add some logging

* Make sure we do not resolve the future right away

* Add a unit test

Author: puddly

tests/test_api.py

@@ -1024,7 +1024,8 @@ async def test_firmware_responding_with_wrong_type_with_correct_seq(
 
     with caplog.at_level(logging.DEBUG):
         with pytest.raises(asyncio.TimeoutError):
-            async with asyncio_timeout(0.5):
+            # We wait beyond 500ms to make sure it triggers
+            async with asyncio_timeout(0.6):
                 await api.send_command(deconz_api.CommandId.aps_data_confirm)
 
     assert (
@@ -1033,6 +1034,71 @@ async def test_firmware_responding_with_wrong_type_with_correct_seq(
     ) in caplog.text
 
 
+async def test_firmware_responding_with_wrong_type_with_correct_seq_eventual_response(
+    api, mock_command_rsp, caplog
+):
+    await api.connect()
+
+    mock_command_rsp(
+        command_id=deconz_api.CommandId.aps_data_confirm,
+        params={},
+        # Completely different response
+        rsp_command=deconz_api.CommandId.version,
+        rsp={
+            "status": deconz_api.Status.SUCCESS,
+            "frame_length": t.uint16_t(9),
+            "version": deconz_api.FirmwareVersion(0x26450900),
+        },
+    )
+
+    with caplog.at_level(logging.DEBUG):
+        _, rx_schema = deconz_api.COMMAND_SCHEMAS[deconz_api.CommandId.aps_data_confirm]
+
+        asyncio.get_running_loop().call_later(
+            0.1,
+            api.data_received,
+            deconz_api.Command(
+                command_id=deconz_api.CommandId.aps_data_confirm,
+                seq=api._seq,
+                payload=t.serialize_dict(
+                    {
+                        "status": deconz_api.Status.SUCCESS,
+                        "frame_length": t.uint16_t(19),
+                        "payload_length": t.uint16_t(12),
+                        "device_state": deconz_api.DeviceState(
+                            network_state=deconz_api.NetworkState2.CONNECTED,
+                            device_state=(
+                                deconz_api.DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE
+                                | deconz_api.DeviceStateFlags.APSDE_DATA_INDICATION
+                            ),
+                        ),
+                        "request_id": t.uint8_t(16),
+                        "dst_addr": t.DeconzAddressEndpoint.deserialize(
+                            b"\x02\xaa\x55\x01"
+                        )[0],
+                        "src_ep": t.uint8_t(0),
+                        "confirm_status": deconz_api.TXStatus.SUCCESS,
+                        "reserved1": t.uint8_t(0),
+                        "reserved2": t.uint8_t(0),
+                        "reserved3": t.uint8_t(0),
+                        "reserved4": t.uint8_t(0),
+                    },
+                    rx_schema,
+                ),
+            ).serialize(),
+        )
+
+        async with asyncio_timeout(0.2):
+            rsp = await api.send_command(deconz_api.CommandId.aps_data_confirm)
+
+    assert rsp["request_id"] == 16
+
+    assert (
+        "Firmware responded incorrectly (Response is mismatched! Sent"
+        " <CommandId.aps_data_confirm: 4>, received <CommandId.version: 13>), retrying"
+    ) not in caplog.text
+
+
 def test_get_command_priority(api):
     assert (
         api._get_command_priority(

zigpy_deconz/api.py

@@ -34,6 +34,7 @@
 
 LOGGER = logging.getLogger(__name__)
 
+MISMATCHED_RESPONSE_TIMEOUT = 0.5
 COMMAND_TIMEOUT = 1.8
 PROBE_TIMEOUT = 2
 REQUEST_RETRY_DELAYS = (0.5, 1.0, 1.5, None)
@@ -420,6 +421,7 @@ def __init__(self, app: Callable, device_config: dict[str, Any]):
 
         # [seq][cmd_id] = [fut1, fut2, ...]
         self._awaiting = collections.defaultdict(lambda: collections.defaultdict(list))
+        self._mismatched_response_timers: dict[int, asyncio.TimerHandle] = {}
         self._command_lock = PriorityLock()
         self._config = device_config
         self._device_state = DeviceState(
@@ -646,15 +648,34 @@ def data_received(self, data: bytes) -> None:
 
         exc = None
 
+        # Make sure to clear any pending mismatched response timers
+        if command.seq in self._mismatched_response_timers:
+            LOGGER.debug("Clearing existing mismatched response timer")
+            self._mismatched_response_timers.pop(command.seq).cancel()
+
         if wrong_fut_cmd_id is not None:
-            exc = MismatchedResponseError(
-                command.command_id,
-                params,
-                (
-                    f"Response is mismatched! Sent {wrong_fut_cmd_id},"
-                    f" received {command.command_id}"
+            LOGGER.debug(
+                "Mismatched response, triggering error in %0.2fs",
+                MISMATCHED_RESPONSE_TIMEOUT,
+            )
+            # The firmware *sometimes* responds with the correct response later
+            self._mismatched_response_timers[
+                command.seq
+            ] = asyncio.get_event_loop().call_later(
+                MISMATCHED_RESPONSE_TIMEOUT,
+                fut.set_exception,
+                MismatchedResponseError(
+                    command.command_id,
+                    params,
+                    (
+                        f"Response is mismatched! Sent {wrong_fut_cmd_id},"
+                        f" received {command.command_id}"
+                    ),
                 ),
             )
+
+            # Make sure we do not resolve the future
+            fut = None
         elif status != Status.SUCCESS:
             exc = CommandError(status, f"{command.command_id}, status: {status}")