Speed up turn on when the power state response takes more than 0.3s (#…

…362)

flux_led/aiodevice.py

@@ -54,8 +54,8 @@
 DEVICE_CONFIG_WAIT_SECONDS = (
     3.5  # time it takes for the device to respond after a config change
 )
-POWER_STATE_TIMEOUT = 0.6
-POWER_CHANGE_ATTEMPTS = 3
+POWER_STATE_TIMEOUT = 1.2
+POWER_CHANGE_ATTEMPTS = 6
 
 
 class AIOWifiLedBulb(LEDENETDevice):
@@ -183,9 +183,9 @@ async def _async_send_state_query(self) -> None:
         await self._async_send_msg(self._protocol.construct_state_query())
 
     async def _async_wait_state_change(
-        self, futures: List["asyncio.Future[Any]"], state: bool
+        self, futures: List["asyncio.Future[Any]"], state: bool, timeout: float
     ) -> bool:
-        done, _ = await asyncio.wait(futures, timeout=POWER_STATE_TIMEOUT)
+        done, _ = await asyncio.wait(futures, timeout=timeout)
         if done and self.is_on == state:
             return True
         return False
@@ -203,7 +203,7 @@ async def _async_set_power_state(
         await self._async_send_msg(self._protocol.construct_state_change(state))
         _LOGGER.debug("%s: Waiting for power state response", self.ipaddr)
         if await self._async_wait_state_change(
-            [state_future, power_state_future], state
+            [state_future, power_state_future], state, POWER_STATE_TIMEOUT * (3 / 8)
         ):
             return True
         if power_state_future.done() and accept_any_power_state_response:
@@ -223,8 +223,15 @@ async def _async_set_power_state(
         if state_future.done():
             state_future = asyncio.Future()
             self._state_futures.append(state_future)
+        pending: "List[asyncio.Future[Any]]" = [state_future]
+        if not power_state_future.done():
+            # If the power state still hasn't responded
+            # we want to stop waiting as soon as it does
+            pending.append(power_state_future)
         await self._async_send_state_query()
-        if await self._async_wait_state_change([state_future], state):
+        if await self._async_wait_state_change(
+            pending, state, POWER_STATE_TIMEOUT * (5 / 8)
+        ):
             return True
         _LOGGER.debug(
             "%s: State query did not return expected power state of %s",
@@ -248,14 +255,24 @@ async def _async_set_power_locked(self, state: bool) -> bool:
 
     async def _async_set_power_state_with_retry(self, state: bool) -> bool:
         for idx in range(POWER_CHANGE_ATTEMPTS):
-            if await self._async_set_power_state(state, False):
+            accept_any_power_state_response = idx > 2
+            if await self._async_set_power_state(
+                state, accept_any_power_state_response
+            ):
                 _LOGGER.debug(
                     "%s: Completed power state change to %s (%s/%s)",
                     self.ipaddr,
                     state,
                     1 + idx,
                     POWER_CHANGE_ATTEMPTS,
                 )
+                if accept_any_power_state_response and self.is_on != state:
+                    # Sometimes these devices respond with "I turned off" and
+                    # they actually turn on when we are requesting to turn on.
+                    assert self._protocol is not None
+                    byte = self._protocol.on_byte if state else self._protocol.off_byte
+                    self._set_power_state(byte)
+                    self._set_power_transition_complete_time()
                 return True
             _LOGGER.debug(
                 "%s: Failed to set power state to %s (%s/%s)",
@@ -264,15 +281,12 @@ async def _async_set_power_state_with_retry(self, state: bool) -> bool:
                 1 + idx,
                 POWER_CHANGE_ATTEMPTS,
             )
-        if await self._async_set_power_state(state, True):
-            _LOGGER.debug("%s: Assuming power state change of %s", self.ipaddr, state)
-            # Sometimes these devices respond with "I turned off" and
-            # they actually even when we are requesting to turn on.
-            assert self._protocol is not None
-            byte = self._protocol.on_byte if state else self._protocol.off_byte
-            self._set_power_state(byte)
-            self._set_power_transition_complete_time()
-            return True
+        _LOGGER.error(
+            "%s: Failed to change power state to %s after %s attempts; Try rebooting the device",
+            self.ipaddr,
+            state,
+            POWER_CHANGE_ATTEMPTS,
+        )
         return False
 
     async def async_set_white_temp(

flux_led/protocol.py

@@ -1774,6 +1774,20 @@ def construct_request_strip_setting(self) -> bytearray:
             inner_pre_constructed=True,
         )
 
+    def construct_state_query(self) -> bytearray:
+        """The bytes to send for a query request."""
+        return self.construct_wrapped_message(
+            super().construct_state_query(),
+            inner_pre_constructed=True,
+        )
+
+    def construct_state_change(self, turn_on: int) -> bytearray:
+        """The bytes to send for a state change request."""
+        return self.construct_wrapped_message(
+            super().construct_state_change(turn_on),
+            inner_pre_constructed=True,
+        )
+
     # ic response
     # 0x00 0x63 0x00 0x32 0x00 0x01 0x04 0x03 0x32 0x01 0xD0 (11)
     # b0 b1 b2 b3 00 01 01 37 00 0b 00 63 00 32 00 01 04 03 32 01 d0 aa
@@ -2083,6 +2097,20 @@ class ProtocolLEDENETCCT(ProtocolLEDENET9Byte):
 
     MIN_BRIGHTNESS = 2
 
+    def construct_state_query(self) -> bytearray:
+        """The bytes to send for a query request."""
+        return self.construct_wrapped_message(
+            super().construct_state_query(),
+            inner_pre_constructed=True,
+        )
+
+    def construct_state_change(self, turn_on: int) -> bytearray:
+        """The bytes to send for a state change request."""
+        return self.construct_wrapped_message(
+            super().construct_state_change(turn_on),
+            inner_pre_constructed=True,
+        )
+
     @property
     def timer_response_len(self) -> int:
         """Return the time response len."""
@@ -2160,6 +2188,20 @@ def construct_levels_change(
 
 
 class ProtocolLEDENETAddressableChristmas(ProtocolLEDENETAddressableBase):
+    def construct_state_query(self) -> bytearray:
+        """The bytes to send for a query request."""
+        return self.construct_wrapped_message(
+            super().construct_state_query(),
+            inner_pre_constructed=True,
+        )
+
+    def construct_state_change(self, turn_on: int) -> bytearray:
+        """The bytes to send for a state change request."""
+        return self.construct_wrapped_message(
+            super().construct_state_change(turn_on),
+            inner_pre_constructed=True,
+        )
+
     @property
     def name(self) -> str:
         """The name of the protocol."""

tests.py

@@ -2392,15 +2392,13 @@ def read_data(expected):
             2, [(255, 255, 255), (0, 255, 0)], 100, MultiColorEffects.STATIC
         )
         assert data == (
-            b"\xb0\xb1\xb2\xb3\x00\x01\x01\x02\x00\x0fY\x00\x0f\xff\xff\xff"
-            b"\x00\xff\x00\x00\x1e\x01d\x00\xe7\xa7"
+            b"\xb0\xb1\xb2\xb3\x00\x01\x01\x03\x00\x0fY\x00\x0f\xff\xff\xff\x00\xff\x00\x00\x1e\x01d\x00\xe7\xa8"
         )
         data = light._protocol.construct_zone_change(
             4, [(255, 255, 255), (0, 255, 0)], 100, MultiColorEffects.STATIC
         )
         assert data == (
-            b"\xb0\xb1\xb2\xb3\x00\x01\x01\x03\x00\x15Y\x00\x15\xff\xff\xff"
-            b"\xff\xff\xff\x00\xff\x00\x00\xff\x00\x00\x1e\x01d\x00\xe9\xb2"
+            b"\xb0\xb1\xb2\xb3\x00\x01\x01\x04\x00\x15Y\x00\x15\xff\xff\xff\xff\xff\xff\x00\xff\x00\x00\xff\x00\x00\x1e\x01d\x00\xe9\xb3"
         )
 
     @patch("flux_led.WifiLedBulb._send_msg")

tests_aio.py

@@ -441,7 +441,7 @@ def _send_data(*args, **kwargs):
             light.is_on is True
         )  # transition time should now be in effect since we forced state
 
-        data = [*(b"\x81\x25\x23\x61\x05\x10\xb6\x00\x98\x19\x04\x25\x0f\xde",) * 10]
+        data = [*(b"\x81\x25\x23\x61\x05\x10\xb6\x00\x98\x19\x04\x25\x0f\xde",) * 14]
         await light.async_turn_off()
         await asyncio.sleep(0)
         # If all we get is on 0x81 responses, the bulb failed to turn off
@@ -455,9 +455,12 @@ def _send_data(*args, **kwargs):
     with patch.object(aiodevice, "POWER_STATE_TIMEOUT", 0.010):
         await asyncio.create_task(light.async_turn_off())
         assert light.is_on is True
-        assert "Failed to set power state to False (1/3)" in caplog.text
-        assert "Failed to set power state to False (2/3)" in caplog.text
-        assert "Failed to set power state to False (3/3)" in caplog.text
+        assert "Failed to set power state to False (1/6)" in caplog.text
+        assert "Failed to set power state to False (2/6)" in caplog.text
+        assert "Failed to set power state to False (3/6)" in caplog.text
+        assert "Failed to set power state to False (4/6)" in caplog.text
+        assert "Failed to set power state to False (5/6)" in caplog.text
+        assert "Failed to set power state to False (6/6)" in caplog.text
 
     with patch.object(light._aio_protocol, "write", _send_data), patch.object(
         aiodevice, "POWER_STATE_TIMEOUT", 0.010
@@ -502,9 +505,12 @@ def _send_data(*args, **kwargs):
     with patch.object(aiodevice, "POWER_STATE_TIMEOUT", 0.010):
         await asyncio.create_task(light.async_turn_on())
         assert light.is_on is False
-        assert "Failed to set power state to True (1/3)" in caplog.text
-        assert "Failed to set power state to True (2/3)" in caplog.text
-        assert "Failed to set power state to True (3/3)" in caplog.text
+        assert "Failed to set power state to True (1/6)" in caplog.text
+        assert "Failed to set power state to True (2/6)" in caplog.text
+        assert "Failed to set power state to True (3/6)" in caplog.text
+        assert "Failed to set power state to True (4/6)" in caplog.text
+        assert "Failed to set power state to True (5/6)" in caplog.text
+        assert "Failed to set power state to True (6/6)" in caplog.text
 
 
 @pytest.mark.asyncio
@@ -2194,6 +2200,54 @@ def _updated_callback(*args, **kwargs):
     await light.async_update()
 
 
+@pytest.mark.asyncio
+async def test_christmas_protocol_device_turn_on(mock_aio_protocol):
+    """Test a christmas protocol device."""
+    light = AIOWifiLedBulb("192.168.1.166")
+
+    def _updated_callback(*args, **kwargs):
+        pass
+
+    task = asyncio.create_task(light.async_setup(_updated_callback))
+    transport, protocol = await mock_aio_protocol()
+    light._aio_protocol.data_received(
+        b"\x81\x1a\x23\x61\x00\x00\x00\xff\x00\x00\x01\x00\x06\x25"
+    )
+    await task
+    assert light.rgb == (0, 255, 0)
+    assert light.brightness == 255
+    assert len(light.effect_list) == 101
+    assert light.protocol == PROTOCOL_LEDENET_ADDRESSABLE_CHRISTMAS
+    assert light.dimmable_effects is False
+    assert light.requires_turn_on is False
+    assert light._protocol.power_push_updates is True
+    assert light._protocol.state_push_updates is False
+
+    data = []
+    written = []
+
+    def _send_data(*args, **kwargs):
+        written.append(args[0])
+        light._aio_protocol.data_received(data.pop(0))
+
+    with patch.object(aiodevice, "POWER_STATE_TIMEOUT", 0.010), patch.object(
+        light._aio_protocol, "write", _send_data
+    ):
+        data = [
+            b"\x81\x1a\x23\x61\x00\x00\x00\xff\x00\x00\x01\x00\x06\x25",
+            b"\x81\x25\x24\x61\x05\x10\xb6\x00\x98\x19\x04\x25\x0f\xdf",
+        ]
+        await light.async_turn_off()
+        await asyncio.sleep(0)
+        assert light.is_on is False
+        assert len(data) == 0
+
+    assert written == [
+        b"\xb0\xb1\xb2\xb3\x00\x01\x01\x00\x00\x04q$\x0f\xa4\x14",
+        b"\xb0\xb1\xb2\xb3\x00\x01\x01\x01\x00\x04\x81\x8a\x8b\x96\xf9",
+    ]
+
+
 @pytest.mark.asyncio
 async def test_christmas_protocol_device(mock_aio_protocol):
     """Test a christmas protocol device."""