WIP Retry aps_data_request on STATUS.BUSY failures. (#51)

* Status enum as int.
* Add zigpy_deconz exceptions.
* Failback and retry aps_data_request command.
Retry aps_data_request() if ConBee is "busy" with other requests.

* Update tests.

Author: Adminiuga

tests/test_api.py

@@ -4,6 +4,7 @@
 import pytest
 
 from zigpy_deconz import api as deconz_api, types as t, uart
+import zigpy_deconz.exception
 
 
 COMMANDS = [*deconz_api.TX_COMMANDS.items(), *deconz_api.RX_COMMANDS.items()]
@@ -109,6 +110,47 @@ def test_data_received(api, monkeypatch):
         my_handler.reset_mock()
 
 
+def test_data_received_unk_status(api, monkeypatch):
+    monkeypatch.setattr(t, 'deserialize', mock.MagicMock(
+        return_value=(mock.sentinel.deserialize_data, b'')))
+    my_handler = mock.MagicMock()
+
+    for cmd, cmd_opts in deconz_api.RX_COMMANDS.items():
+        cmd_id, unsolicited = cmd_opts[0], cmd_opts[2]
+        payload = b'\x01\x02\x03\x04'
+        status = t.uint8_t(0xfe).serialize()
+        data = cmd_id.to_bytes(1, 'big') + b'\x00' + \
+            status + b'\x00\x00' + payload
+        setattr(api, '_handle_{}'.format(cmd), my_handler)
+        api._awaiting[0] = (mock.MagicMock(), )
+        api.data_received(data)
+        assert t.deserialize.call_count == 1
+        assert t.deserialize.call_args[0][0] == payload
+        if unsolicited:
+            assert my_handler.call_count == 0
+        else:
+            assert my_handler.call_count == 1
+        t.deserialize.reset_mock()
+        my_handler.reset_mock()
+
+
+def test_data_received_unk_cmd(api, monkeypatch):
+    monkeypatch.setattr(t, 'deserialize', mock.MagicMock(
+        return_value=(mock.sentinel.deserialize_data, b'')))
+
+    for cmd_id in range(0, 255):
+        if cmd_id in api._commands_by_id:
+            continue
+        payload = b'\x01\x02\x03\x04'
+        status = t.uint8_t(0x00).serialize()
+        data = cmd_id.to_bytes(1, 'big') + b'\x00' + \
+            status + b'\x00\x00' + payload
+        api._awaiting[0] = (mock.MagicMock(), )
+        api.data_received(data)
+        assert t.deserialize.call_count == 0
+        t.deserialize.reset_mock()
+
+
 def test_simplified_beacon(api):
     api._handle_simplified_beacon(
         (0x0007, 0x1234, 0x5678, 0x19, 0x00, 0x01)
@@ -166,3 +208,71 @@ def mock_cmd(*args, **kwargs):
     res = await api._aps_data_indication()
     assert res is None
     assert api._data_indication is False
+
+
+@pytest.mark.asyncio
+async def test_aps_data_request(api):
+    params = [
+        0x00,  # req  id
+        t.DeconzAddressEndpoint.deserialize(
+            b'\x02\xaa\x55\x01')[0],  # dst + ep
+        0x0104,  # profile id
+        0x0007,  # cluster id
+        0x01,  # src ep
+        b'aps payload'
+    ]
+
+    mock_cmd = mock.MagicMock(
+        side_effect=asyncio.coroutine(mock.MagicMock()))
+    api._command = mock_cmd
+
+    await api.aps_data_request(*params)
+    assert mock_cmd.call_count == 1
+
+
+@pytest.mark.asyncio
+async def test_aps_data_request_timeout(api, monkeypatch):
+    params = [
+        0x00,  # req  id
+        t.DeconzAddressEndpoint.deserialize(
+            b'\x02\xaa\x55\x01')[0],  # dst + ep
+        0x0104,  # profile id
+        0x0007,  # cluster id
+        0x01,  # src ep
+        b'aps payload'
+    ]
+
+    mock_cmd = mock.MagicMock(return_value=asyncio.Future())
+    api._command = mock_cmd
+    monkeypatch.setattr(deconz_api, 'COMMAND_TIMEOUT', .1)
+
+    with pytest.raises(asyncio.TimeoutError):
+        await api.aps_data_request(*params)
+        assert mock_cmd.call_count == 1
+
+
+@pytest.mark.asyncio
+async def test_aps_data_request_busy(api, monkeypatch):
+    params = [
+        0x00,  # req  id
+        t.DeconzAddressEndpoint.deserialize(
+            b'\x02\xaa\x55\x01')[0],  # dst + ep
+        0x0104,  # profile id
+        0x0007,  # cluster id
+        0x01,  # src ep
+        b'aps payload'
+    ]
+
+    res = asyncio.Future()
+    exc = zigpy_deconz.exception.CommandError(deconz_api.STATUS.BUSY, 'busy')
+    res.set_exception(exc)
+    mock_cmd = mock.MagicMock(return_value=res)
+
+    api._command = mock_cmd
+    monkeypatch.setattr(deconz_api, 'COMMAND_TIMEOUT', .1)
+    sleep = mock.MagicMock(side_effect=asyncio.coroutine(mock.MagicMock()))
+    monkeypatch.setattr(asyncio, 'sleep', sleep)
+
+    with pytest.raises(zigpy_deconz.exception.CommandError):
+        await api.aps_data_request(*params)
+        assert mock_cmd.call_count == 4

tests/test_exception.py

@@ -0,0 +1,9 @@
+from unittest import mock
+
+import zigpy_deconz.exception
+
+
+def test_command_error():
+    ex = zigpy_deconz.exception.CommandError(mock.sentinel.status,
+                                             mock.sentinel.message)
+    assert ex.status is mock.sentinel.status

zigpy_deconz/api.py

@@ -5,6 +5,7 @@
 
 from . import uart
 from . import types as t
+from zigpy_deconz.exception import CommandError
 
 LOGGER = logging.getLogger(__name__)
 
@@ -76,7 +77,7 @@
 NETWORK_PARAMETER_BY_ID = {v[0]: (k, v[1]) for k, v in NETWORK_PARAMETER.items()}
 
 
-class STATUS(enum.Enum):
+class STATUS(t.uint8_t, enum.Enum):
     SUCCESS = 0
     FAILURE = 1
     BUSY = 2
@@ -150,15 +151,20 @@ def data_received(self, data):
             return
         command = self._commands_by_id[data[0]]
         seq = data[1]
-        status = data[2]
+        try:
+            status = STATUS(data[2])
+        except ValueError:
+            status = data[2]
         try:
             data, _ = t.deserialize(data[5:], RX_COMMANDS[command][1])
         except Exception:
             LOGGER.warning("Failed to deserialize frame: %s", binascii.hexlify(data))
         if RX_COMMANDS[command][2]:
             fut, = self._awaiting.pop(seq)
-            if status is not STATUS.SUCCESS.value:
-                fut.set_exception(Exception('%s, status: %s' % (command, status, )))
+            if status != STATUS.SUCCESS:
+                fut.set_exception(
+                    CommandError(status, '%s, status: %s' % (command,
+                                                             status, )))
                 return
             fut.set_result(data)
         getattr(self, '_handle_%s' % (command, ))(data)
@@ -265,16 +271,25 @@ def _handle_aps_data_indication(self, data):
     async def aps_data_request(self, req_id, dst_addr_ep, profile, cluster, src_ep, aps_payload):
         dst = dst_addr_ep.serialize()
         length = len(dst) + len(aps_payload) + 11
-        try:
-            return await asyncio.wait_for(
-                self._command('aps_data_request', length, req_id, 0,
-                              dst_addr_ep, profile, cluster, src_ep,
-                              aps_payload, 0, 0),
-                timeout=COMMAND_TIMEOUT
-            )
-        except asyncio.TimeoutError:
-            LOGGER.warning("No response to aps_data_request command")
-            raise
+        delays = (0.5, 1.0, 1.5, None)
+        for delay in delays:
+            try:
+                return await asyncio.wait_for(
+                    self._command('aps_data_request', length, req_id, 0,
+                                  dst_addr_ep, profile, cluster, src_ep,
+                                  aps_payload, 2, 0),
+                    timeout=COMMAND_TIMEOUT
+                )
+            except asyncio.TimeoutError:
+                LOGGER.warning("No response to aps_data_request command")
+                raise
+            except CommandError as ex:
+                LOGGER.debug("'aps_data_request' failure: %s", ex)
+                if delay is not None and ex.status == STATUS.BUSY:
+                    LOGGER.debug("retrying 'aps_data_request' in %ss", delay)
+                    await asyncio.sleep(delay)
+                    continue
+                raise
 
     def _handle_aps_data_request(self, data):
         LOGGER.debug("APS data request response: %s", data)

zigpy_deconz/exception.py

@@ -0,0 +1,15 @@
+from zigpy.exceptions import ZigbeeException
+
+
+class DeconException(ZigbeeException):
+    pass
+
+
+class CommandError(DeconException):
+    def __init__(self, status, *args, **kwargs):
+        self._status = status
+        super().__init__(*args, **kwargs)
+
+    @property
+    def status(self):
+        return self._status