Move retrying out of connect and into startup_reset (#696)

* Move retrying out of `connect` and into `startup_reset`

* Constant tweaking

* Better debug logging for long CANCEL sequences

* Fix tests

Author: puddly

bellows/ash.py

@@ -16,6 +16,7 @@
 from zigpy.types import BaseDataclassMixin
 
 import bellows.types as t
+from bellows.zigbee.util import run_length_debug
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -596,8 +597,13 @@ def _write_frame(
             raise NcpFailure("Transport is closed, cannot send frame")
 
         if _LOGGER.isEnabledFor(logging.DEBUG):
-            prefix_str = "".join([f"{r.name} + " for r in prefix])
-            suffix_str = "".join([f" + {r.name}" for r in suffix])
+            prefix_str = run_length_debug(
+                [p.name for p in prefix], joiner=" + ", suffix=" "
+            )
+            suffix_str = run_length_debug(
+                [s.name for s in suffix], joiner=" + ", prefix=" "
+            )
+
             _LOGGER.debug("Sending frame %s%r%s", prefix_str, frame, suffix_str)
 
         data = bytes(prefix) + self._stuff_bytes(frame.to_bytes()) + bytes(suffix)
@@ -713,7 +719,4 @@ async def send_data(self, data: bytes) -> None:
 
     def send_reset(self) -> None:
         # Some adapters seem to send a NAK immediately but still process the reset frame
-        # if one eventually makes it through
-        self._write_frame(RstFrame(), prefix=(Reserved.CANCEL,))
-        self._write_frame(RstFrame(), prefix=(Reserved.CANCEL,))
-        self._write_frame(RstFrame(), prefix=(Reserved.CANCEL,))
+        self._write_frame(RstFrame(), prefix=40 * (Reserved.CANCEL,))

bellows/ezsp/__init__.py

@@ -26,7 +26,7 @@
 
 from . import v4, v5, v6, v7, v8, v9, v10, v11, v12, v13, v14, v16, v17
 
-RESET_ATTEMPTS = 5
+RESET_ATTEMPTS = 3
 
 EZSP_LATEST = v17.EZSPv17.VERSION
 LOGGER = logging.getLogger(__name__)
@@ -109,7 +109,7 @@ def is_tcp_serial_port(self) -> bool:
         parsed_path = urllib.parse.urlparse(self._config[conf.CONF_DEVICE_PATH])
         return parsed_path.scheme == "socket"
 
-    async def startup_reset(self) -> None:
+    async def _startup_reset(self) -> None:
         """Start EZSP and reset the stack."""
         # `zigbeed` resets on startup
         if self.is_tcp_serial_port:
@@ -128,15 +128,12 @@ async def startup_reset(self) -> None:
         await self.version()
         await self.get_xncp_features()
 
-    async def connect(self, *, use_thread: bool = True) -> None:
-        assert self._gw is None
-        self._gw = await bellows.uart.connect(self._config, self, use_thread=use_thread)
-
+    async def startup_reset(self) -> None:
         for attempt in range(RESET_ATTEMPTS):
             self._protocol = v4.EZSPv4(self.handle_callback, self._gw)
 
             try:
-                await self.startup_reset()
+                await self._startup_reset()
                 break
             except Exception as exc:
                 if attempt + 1 < RESET_ATTEMPTS:
@@ -151,6 +148,11 @@ async def connect(self, *, use_thread: bool = True) -> None:
                 await self.disconnect()
                 raise
 
+    async def connect(self, *, use_thread: bool = True) -> None:
+        assert self._gw is None
+        self._gw = await bellows.uart.connect(self._config, self, use_thread=use_thread)
+        await self.startup_reset()
+
     async def reset(self):
         LOGGER.debug("Resetting EZSP")
         self.stop_ezsp()

bellows/uart.py

@@ -10,7 +10,7 @@
 import bellows.types as t
 
 LOGGER = logging.getLogger(__name__)
-RESET_TIMEOUT = 3
+RESET_TIMEOUT = 2.5
 
 
 class Gateway(zigpy.serial.SerialProtocol):

bellows/zigbee/util.py

@@ -1,3 +1,4 @@
+from collections.abc import Sequence
 import logging
 import math
 
@@ -129,3 +130,32 @@ def map_energy_to_rssi(lqi: float) -> float:
         x_0=RSSI_MIN + 0.45 * (RSSI_MAX - RSSI_MIN),
         k=0.13,
     )
+
+
+def run_length_debug(
+    items: Sequence[str],
+    joiner: str,
+    prefix: str = "",
+    suffix: str = "",
+    default: str = "",
+) -> str:
+    """Create a run-length encoded debug string from a sequence of strings."""
+    counts = []
+    unique_items = []
+
+    for item in items:
+        if unique_items and unique_items[-1] == item:
+            counts[-1] += 1
+        else:
+            counts.append(1)
+            unique_items.append(item)
+
+    result = joiner.join(
+        f"{count}*{item}" if count > 1 else item
+        for item, count in zip(unique_items, counts)
+    )
+
+    if not result:
+        return default
+
+    return prefix + result + suffix

tests/test_ash.py

@@ -438,10 +438,7 @@ async def test_ash_protocol_startup(caplog):
 
     assert ezsp.reset_received.mock_calls == [call(t.NcpResetCode.RESET_SOFTWARE)]
     assert protocol._write_frame.mock_calls == [
-        # We send three
-        call(ash.RstFrame(), prefix=(ash.Reserved.CANCEL,)),
-        call(ash.RstFrame(), prefix=(ash.Reserved.CANCEL,)),
-        call(ash.RstFrame(), prefix=(ash.Reserved.CANCEL,)),
+        call(ash.RstFrame(), prefix=40 * (ash.Reserved.CANCEL,))
     ]
 
     protocol._write_frame.reset_mock()

tests/test_ezsp.py

@@ -299,12 +299,12 @@ async def test_ezsp_connect_failure(disconnect_mock, reset_mock, version_mock):
             await ezsp.connect()
 
     assert conn_mock.await_count == 1
-    assert reset_mock.await_count == 5
-    assert version_mock.await_count == 5
+    assert reset_mock.await_count == 3
+    assert version_mock.await_count == 3
     assert disconnect_mock.call_count == 1
 
 
-@pytest.mark.parametrize("failures_before_success", [1, 2, 3, 4])
+@pytest.mark.parametrize("failures_before_success", [1, 2])
 @patch.object(EZSP, "disconnect", new_callable=AsyncMock)
 async def test_ezsp_connect_retry_success(disconnect_mock, failures_before_success):
     """Test connection succeeding after N failures."""
@@ -319,7 +319,7 @@ async def startup_reset_mock():
     with patch("bellows.uart.connect"):
         ezsp = make_ezsp(version=4)
 
-        with patch.object(ezsp, "startup_reset", side_effect=startup_reset_mock):
+        with patch.object(ezsp, "_startup_reset", side_effect=startup_reset_mock):
             await ezsp.connect()
 
     assert call_count == failures_before_success + 1