Improve reliablity of turn on for devices that are slow to update sta…

…te (#359)

flux_led/aiodevice.py

@@ -1,9 +1,8 @@
 import asyncio
-import contextlib
 from datetime import datetime
 import logging
 import time
-from typing import Callable, Coroutine, Dict, List, Optional, Tuple
+from typing import Any, Callable, Dict, List, Optional, Tuple, Union
 
 from .aioprotocol import AIOLEDENETProtocol
 from .aioscanner import AIOBulbScanner
@@ -32,6 +31,8 @@
 from .protocol import (
     POWER_RESTORE_BYTES_TO_POWER_RESTORE,
     REMOTE_CONFIG_BYTES_TO_REMOTE_CONFIG,
+    LEDENETOriginalRawState,
+    LEDENETRawState,
     PowerRestoreState,
     PowerRestoreStates,
     ProtocolLEDENET8Byte,
@@ -43,6 +44,7 @@
 from .scanner import FluxLEDDiscovery
 from .timer import LedTimer
 from .utils import color_temp_to_white_levels, rgbw_brightness, rgbww_brightness
+from .const import PUSH_UPDATE_INTERVAL, NEVER_TIME
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -52,20 +54,8 @@
 DEVICE_CONFIG_WAIT_SECONDS = (
     3.5  # time it takes for the device to respond after a config change
 )
-POWER_STATE_TIMEOUT = 1.2  # number of seconds before declaring on/off failed
-
-#
-# PUSH_UPDATE_INTERVAL reduces polling the device for state when its off
-# since we do not care about the state when its off. When it turns on
-# the device will push its new state to us anyways (except for buggy firmwares
-# are identified in protocol.py)
-#
-# The downside to a longer polling interval for OFF is the
-# time to declare the device offline is MAX_UPDATES_WITHOUT_RESPONSE*PUSH_UPDATE_INTERVAL
-#
-PUSH_UPDATE_INTERVAL = 90  # seconds
-
-NEVER_TIME = -PUSH_UPDATE_INTERVAL
+POWER_STATE_TIMEOUT = 0.6
+POWER_CHANGE_ATTEMPTS = 3
 
 
 class AIOWifiLedBulb(LEDENETDevice):
@@ -92,8 +82,11 @@ def __init__(
         self._device_config_future: asyncio.Future[bool] = asyncio.Future()
         self._remote_config_future: asyncio.Future[bool] = asyncio.Future()
         self._device_config_setup = False
-        self._on_futures: List["asyncio.Future[bool]"] = []
-        self._off_futures: List["asyncio.Future[bool]"] = []
+        self._power_state_lock = asyncio.Lock()
+        self._power_state_futures: List["asyncio.Future[bool]"] = []
+        self._state_futures: List[
+            "asyncio.Future[Union[LEDENETRawState, LEDENETOriginalRawState]]"
+        ] = []
         self._determine_protocol_future: Optional["asyncio.Future[bool]"] = None
         self._updated_callback: Optional[Callable[[], None]] = None
         self._updates_without_response = 0
@@ -189,86 +182,96 @@ async def _async_send_state_query(self) -> None:
         assert self._protocol is not None
         await self._async_send_msg(self._protocol.construct_state_query())
 
-    async def _async_execute_and_wait_for(
-        self,
-        futures: List["asyncio.Future[bool]"],
-        coro: Callable[[], Coroutine[None, None, None]],
+    async def _async_wait_state_change(
+        self, futures: List["asyncio.Future[Any]"], state: bool
     ) -> bool:
+        _, done = await asyncio.wait(futures, timeout=POWER_STATE_TIMEOUT)
+        if done and self.is_on == state:
+            return True
+        return False
+
+    async def _async_set_power_state(
+        self, state: bool, accept_any_power_state_response: bool
+    ) -> bool:
+        assert self._protocol is not None
         future: "asyncio.Future[bool]" = asyncio.Future()
-        futures.append(future)
-        await coro()
+        state_future: "asyncio.Future[Union[LEDENETRawState, LEDENETOriginalRawState]]" = (
+            asyncio.Future()
+        )
+        self._power_state_futures.append(future)
+        self._state_futures.append(state_future)
+        await self._async_send_msg(self._protocol.construct_state_change(state))
         _LOGGER.debug("%s: Waiting for power state response", self.ipaddr)
-        with contextlib.suppress(asyncio.TimeoutError):
-            await asyncio.wait_for(asyncio.shield(future), POWER_STATE_TIMEOUT / 2)
+        if await self._async_wait_state_change([state_future, future], state):
             return True
-        _LOGGER.debug(
-            "%s: Did not get expected power state response, sending state query",
-            self.ipaddr,
+        responded = future.done()
+        if responded and accept_any_power_state_response:
+            # The magic home app will accept any response as success
+            # so after a few tries, we do as well.
+            return True
+        elif responded:
+            _LOGGER.debug(
+                "%s: Bulb power state change taking longer than expected to %s, sending state query",
+                self.ipaddr,
+                state,
+            )
+        else:
+            _LOGGER.debug(
+                "%s: Bulb failed to respond, sending state query", self.ipaddr
+            )
+        state_future: "asyncio.Future[Union[LEDENETRawState, LEDENETOriginalRawState]]" = (
+            asyncio.Future()
         )
         await self._async_send_state_query()
-        with contextlib.suppress(asyncio.TimeoutError):
-            await asyncio.wait_for(future, POWER_STATE_TIMEOUT / 2)
+        if await self._async_wait_state_change([state_future], state):
             return True
         _LOGGER.debug(
-            "%s: State query did not return expected power state", self.ipaddr
+            "%s: State query did not return expected power state of %s",
+            self.ipaddr,
+            state,
         )
         return False
 
-    async def _async_turn_on(self) -> None:
-        assert self._protocol is not None
-        await self._async_send_msg(self._protocol.construct_state_change(True))
-
-    async def _async_turn_off_on(self) -> None:
-        await self._async_turn_off()
-        await self._async_turn_on()
-
     async def async_turn_on(self) -> bool:
         """Turn on the device."""
-        calls = (
-            self._async_turn_on,
-            self._async_turn_on,
-            self._async_turn_on,
-            self._async_turn_off_on,
-            self._async_turn_on,
-            self._async_turn_on,
-        )
-        for idx, call in enumerate(calls):
-            if (
-                await self._async_execute_and_wait_for(self._on_futures, call)
-                or self.is_on
-            ):
-                return True
-            _LOGGER.debug(
-                "%s: Failed to turn on (%s/%s)", self.ipaddr, 1 + idx, len(calls)
-            )
-        return False
-
-    async def _async_turn_off(self) -> None:
-        assert self._protocol is not None
-        await self._async_send_msg(self._protocol.construct_state_change(False))
-
-    async def _async_turn_on_off(self) -> None:
-        await self._async_turn_on()
-        await self._async_turn_off()
+        return await self._async_set_power_locked(True)
 
     async def async_turn_off(self) -> bool:
         """Turn off the device."""
-        calls = (
-            self._async_turn_off,
-            self._async_turn_off,
-            self._async_turn_on_off,
-            self._async_turn_off,
-            self._async_turn_off,
-        )
-        for idx, call in enumerate(calls):
-            if (
-                await self._async_execute_and_wait_for(self._off_futures, call)
-                or not self.is_on
-            ):
+        return await self._async_set_power_locked(False)
+
+    async def _async_set_power_locked(self, state: bool) -> bool:
+        async with self._power_state_lock:
+            self._power_state_transition_complete_time = NEVER_TIME
+            return await self._async_set_power_state_with_retry(state)
+
+    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):
+                _LOGGER.debug(
+                    "%s: Completed power state change to %s (%s/%s)",
+                    self.ipaddr,
+                    state,
+                    1 + idx,
+                    POWER_CHANGE_ATTEMPTS,
+                )
                 return True
             _LOGGER.debug(
-                "%s: Failed to turn off (%s/%s)", self.ipaddr, 1 + idx, len(calls)
+                "%s: Failed to set power state to %s (%s/%s)",
+                self.ipaddr,
+                state,
+                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
         return False
 
     async def async_set_white_temp(
@@ -354,7 +357,7 @@ async def _async_process_levels_change(
         for idx, msg in enumerate(msgs):
             await self._async_send_msg(msg)
             if idx > 0:
-                self._process_futures_and_callbacks()
+                self._process_callbacks()
                 await asyncio.sleep(COMMAND_SPACING_DELAY)
                 self._set_transition_complete_time()
 
@@ -680,8 +683,10 @@ def _async_process_message(self, msg: bytes) -> None:
 
         if self._protocol.is_valid_state_response(msg):
             self._async_process_state_response(msg)
+            self._process_state_futures()
         elif self._protocol.is_valid_power_state_response(msg):
             self.process_power_state_response(msg)
+            self._process_power_futures()
         elif self._protocol.is_valid_get_time_response(msg):
             self.process_time_response(msg)
         elif self._protocol.is_valid_timers_response(msg):
@@ -704,15 +709,25 @@ def _async_process_message(self, msg: bytes) -> None:
             return
         if not changed_state and self.raw_state == prev_state:
             return
-        self._process_futures_and_callbacks()
+        self._process_callbacks()
 
-    def _process_futures_and_callbacks(self) -> None:
-        """Called when state changes."""
-        futures = self._on_futures if self.is_on else self._off_futures
-        for future in futures:
+    def _process_state_futures(self) -> None:
+        """Process power future responses."""
+        assert self.raw_state is not None
+        for future in self._state_futures:
+            if not future.done():
+                future.set_result(self.raw_state)
+        self._state_futures.clear()
+
+    def _process_power_futures(self) -> None:
+        """Process power future responses."""
+        for future in self._power_state_futures:
             if not future.done():
-                future.set_result(True)
-        futures.clear()
+                future.set_result(self.is_on)
+        self._power_state_futures.clear()
+
+    def _process_callbacks(self) -> None:
+        """Called when state changes."""
         assert self._updated_callback is not None
         try:
             self._updated_callback()

flux_led/base_device.py

@@ -5,9 +5,12 @@
 import time
 from typing import Dict, Iterable, List, Optional, Set, Tuple, Type, Union
 
+from .const import NEVER_TIME
+
 from .const import (  # imported for back compat, remove once Home Assistant no longer uses
     ADDRESSABLE_STATE_CHANGE_LATENCY,
     ATTR_MODEL,
+    POWER_STATE_CHANGE_LATENCY,
     ATTR_MODEL_DESCRIPTION,
     CHANNEL_STATES,
     COLOR_MODE_CCT,
@@ -38,6 +41,7 @@
     STATE_CHANGE_LATENCY,
     STATE_COOL_WHITE,
     STATE_GREEN,
+    STATE_POWER_STATE,
     STATE_RED,
     STATE_WARM_WHITE,
     STATIC_MODES,
@@ -214,6 +218,7 @@ def __init__(
         self._mode: Optional[str] = None
         self._transition_complete_time: float = 0
         self._preset_pattern_transition_complete_time: float = 0
+        self._power_state_transition_complete_time: float = 0
         self._last_effect_brightness: int = 100
         self._device_config: Optional[LEDENETAddressableDeviceConfiguration] = None
 
@@ -758,6 +763,8 @@ def process_state_response(self, rx: bytes) -> bool:
 
         now_time = time.monotonic()
         transition_states = set()
+        if now_time < self._power_state_transition_complete_time:
+            transition_states.add(STATE_POWER_STATE)
         if now_time < self._transition_complete_time:
             # Do not update the channel states if a transition is
             # in progress as the state will not be correct
@@ -1129,7 +1136,7 @@ def _set_transition_complete_time(self) -> None:
             self._transition_complete_time,
         )
         # If we are doing a state transition cancel and preset pattern transition
-        self._preset_pattern_transition_complete_time = 0
+        self._preset_pattern_transition_complete_time = NEVER_TIME
 
     def _set_preset_pattern_transition_complete_time(self) -> None:
         """Set the time we expect the preset_pattern transition will be completed."""
@@ -1138,12 +1145,25 @@ def _set_preset_pattern_transition_complete_time(self) -> None:
             time.monotonic() + PRESET_PATTERN_CHANGE_LATENCY
         )
         _LOGGER.debug(
-            "%s: Mode trransition time is %s, set _preset_pattern_transition_complete_time to %s",
+            "%s: Mode transition time is %s, set _preset_pattern_transition_complete_time to %s",
             self.ipaddr,
             PRESET_PATTERN_CHANGE_LATENCY,
             self._preset_pattern_transition_complete_time,
         )
 
+    def _set_power_transition_complete_time(self) -> None:
+        """Set the time we expect the power transition will be completed."""
+        assert self.raw_state is not None
+        self._power_state_transition_complete_time = (
+            time.monotonic() + POWER_STATE_CHANGE_LATENCY
+        )
+        _LOGGER.debug(
+            "%s: Mode transition time is %s, set _power_state_transition_complete_time to %s",
+            self.ipaddr,
+            POWER_STATE_CHANGE_LATENCY,
+            self._power_state_transition_complete_time,
+        )
+
     def getRgb(self) -> Tuple[int, int, int]:
         if self.color_mode not in COLOR_MODES_RGB:
             return (255, 255, 255)

flux_led/const.py

@@ -60,7 +60,8 @@ class MultiColorEffects(Enum):
 COLOR_MODE_RGBWW: Final = "RGBWW"
 COLOR_MODE_ADDRESSABLE: Final = "ADDRESSABLE"
 
-STATE_CHANGE_LATENCY: Final = 1
+POWER_STATE_CHANGE_LATENCY: Final = 3
+STATE_CHANGE_LATENCY: Final = 2
 ADDRESSABLE_STATE_CHANGE_LATENCY: Final = 5
 PRESET_PATTERN_CHANGE_LATENCY: Final = 40  # Time to switch to music mode
 
@@ -139,3 +140,17 @@ class MultiColorEffects(Enum):
 MUSIC_SEGMENTS_MAX: Final = 64
 MUSIC_PIXELS_MAX: Final = 960
 MUSIC_PIXELS_PER_SEGMENT_MAX: Final = 150
+
+
+#
+# PUSH_UPDATE_INTERVAL reduces polling the device for state when its off
+# since we do not care about the state when its off. When it turns on
+# the device will push its new state to us anyways (except for buggy firmwares
+# are identified in protocol.py)
+#
+# The downside to a longer polling interval for OFF is the
+# time to declare the device offline is MAX_UPDATES_WITHOUT_RESPONSE*PUSH_UPDATE_INTERVAL
+#
+PUSH_UPDATE_INTERVAL = 90  # seconds
+
+NEVER_TIME = -PUSH_UPDATE_INTERVAL

flux_led/protocol.py

@@ -946,7 +946,7 @@ def is_valid_power_state_response(self, msg: bytes) -> bool:
             or msg[2] not in (self.on_byte, self.off_byte)
         ):
             return False
-        return self.is_checksum_correct(msg)
+        return True  # checksum does not always match
 
     def _is_start_of_power_state_response(self, data: bytes) -> bool:
         """Check if a message is the start of a state response."""