diff --git a/tests/test_api.py b/tests/test_api.py index 6e6d3c0..8bc03e7 100644 --- a/tests/test_api.py +++ b/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" + " , received ), retrying" + ) not in caplog.text + + def test_get_command_priority(api): assert ( api._get_command_priority( diff --git a/zigpy_deconz/api.py b/zigpy_deconz/api.py index 50034f9..f63e218 100644 --- a/zigpy_deconz/api.py +++ b/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}") @@ -665,9 +686,10 @@ def data_received(self, data: bytes) -> None: else: fut.set_exception(exc) except asyncio.InvalidStateError: - LOGGER.warning( - "Duplicate or delayed response for 0x:%02x sequence", + LOGGER.debug( + "Duplicate or delayed response for seq %s (awaiting %s)", command.seq, + self._awaiting[command.seq], ) if exc is not None: