Prevent tplink missing devices and unavailable state (#39762)

* Adds self to codeowners for tplink

* Adds retry to update to prevent missing devices

* Runs through isort and corrects async commit

* Runs through black

* Runs through pre-checks

* Corrects and matches var names

* Re-runs through black

* Corrects var name

* Removes the retry loop and in favor of async add

* Cleanup imports

* Removes no longer valid test

* Removes is_ready and only log retry once

* Corrects switch logging vars

* Adds list of entities to add_entities

* Consumes exception for attempt_update

* Consumes specific exception

* Removes unnecessary update

* Reducing back to 2 seconds

* Removes useless return

* Call get_sysinfo for all at once

* Formated black

* Adds missing docstirng

* Corrects docstring

* Update homeassistant/components/tplink/light.py

Co-authored-by: Anders Melchiorsen <amelchio@nogoto.net>

* Corrects sysinfo call

* Adds default for host vars

* Adds log when device responds again

* Revert host alias default

* Removes unncessary host var

* Removes host var

* Get device details from sysinfo

* Use host and alias for log msg

* Gets hosts from smartbulb

* Changes retry logging to debug

* Attempts coverage add

* Removes unused import

* Updates tests for new retry

* Runs through isort

* Removes unneeded try

* Prevents static entries from failing integration

* Format black

* Forces an update after turn on off

* Remove common test

* Revert update after turn_on off

* Adds patch for sleep_time 0

* Returns False when update fails

Co-authored-by: Anders Melchiorsen <amelchio@nogoto.net>

.coveragerc

@@ -915,6 +915,7 @@ omit =
     homeassistant/components/torque/sensor.py
     homeassistant/components/totalconnect/*
     homeassistant/components/touchline/climate.py
+    homeassistant/components/tplink/common.py
     homeassistant/components/tplink/switch.py
     homeassistant/components/tplink_lte/*
     homeassistant/components/traccar/device_tracker.py

CODEOWNERS

@@ -453,7 +453,7 @@ homeassistant/components/tmb/* @alemuro
 homeassistant/components/todoist/* @boralyl
 homeassistant/components/toon/* @frenck
 homeassistant/components/totalconnect/* @austinmroczek
-homeassistant/components/tplink/* @rytilahti
+homeassistant/components/tplink/* @rytilahti @thegardenmonkey
 homeassistant/components/traccar/* @ludeeus
 homeassistant/components/tradfri/* @ggravlingen
 homeassistant/components/trafikverket_train/* @endor-force

homeassistant/components/tplink/common.py

@@ -1,8 +1,6 @@
 """Common code for tplink."""
-import asyncio
-from datetime import timedelta
 import logging
-from typing import Any, Callable, List
+from typing import List
 
 from pyHS100 import (
     Discover,
@@ -113,89 +111,19 @@ def get_static_devices(config_data) -> SmartDevices:
     for type_ in [CONF_LIGHT, CONF_SWITCH, CONF_STRIP, CONF_DIMMER]:
         for entry in config_data[type_]:
             host = entry["host"]
-
-            if type_ == CONF_LIGHT:
-                lights.append(SmartBulb(host))
-            elif type_ == CONF_SWITCH:
-                switches.append(SmartPlug(host))
-            elif type_ == CONF_STRIP:
-                try:
-                    ss_host = SmartStrip(host)
-                except SmartDeviceException as sde:
-                    _LOGGER.error(
-                        "Failed to setup SmartStrip at %s: %s; not retrying", host, sde
-                    )
-                    continue
-                for plug in ss_host.plugs.values():
-                    switches.append(plug)
-            # Dimmers need to be defined as smart plugs to work correctly.
-            elif type_ == CONF_DIMMER:
-                lights.append(SmartPlug(host))
-
-    return SmartDevices(lights, switches)
-
-
-async def async_add_entities_retry(
-    hass: HomeAssistantType,
-    async_add_entities: Callable[[List[Any], bool], None],
-    objects: List[Any],
-    callback: Callable[[Any, Callable], None],
-    interval: timedelta = timedelta(seconds=60),
-):
-    """
-    Add entities now and retry later if issues are encountered.
-
-    If the callback throws an exception or returns false, that
-    object will try again a while later.
-    This is useful for devices that are not online when hass starts.
-    :param hass:
-    :param async_add_entities: The callback provided to a
-    platform's async_setup.
-    :param objects: The objects to create as entities.
-    :param callback: The callback that will perform the add.
-    :param interval: THe time between attempts to add.
-    :return: A callback to cancel the retries.
-    """
-    add_objects = objects.copy()
-
-    is_cancelled = False
-
-    def cancel_interval_callback():
-        nonlocal is_cancelled
-        is_cancelled = True
-
-    async def process_objects_loop(delay: int):
-        if is_cancelled:
-            return
-
-        await process_objects()
-
-        if not add_objects:
-            return
-
-        await asyncio.sleep(delay)
-
-        hass.async_create_task(process_objects_loop(delay))
-
-    async def process_objects(*args):
-        # Process each object.
-        for add_object in list(add_objects):
-            # Call the individual item callback.
             try:
-                _LOGGER.debug("Attempting to add object of type %s", type(add_object))
+                if type_ == CONF_LIGHT:
-                result = await hass.async_add_job(
+                    lights.append(SmartBulb(host))
-                    callback, add_object, async_add_entities
+                elif type_ == CONF_SWITCH:
+                    switches.append(SmartPlug(host))
+                elif type_ == CONF_STRIP:
+                    for plug in SmartStrip(host).plugs.values():
+                        switches.append(plug)
+                # Dimmers need to be defined as smart plugs to work correctly.
+                elif type_ == CONF_DIMMER:
+                    lights.append(SmartPlug(host))
+            except SmartDeviceException as sde:
+                _LOGGER.error(
+                    "Failed to setup device %s due to %s; not retrying", host, sde
                 )
-            except SmartDeviceException as ex:
+    return SmartDevices(lights, switches)
-                _LOGGER.debug(str(ex))
-                result = False
-
-            if result is True or result is None:
-                _LOGGER.debug("Added object")
-                add_objects.remove(add_object)
-            else:
-                _LOGGER.debug("Failed to add object, will try again later")
-
-    await process_objects_loop(interval.seconds)
-
-    return cancel_interval_callback

homeassistant/components/tplink/light.py

@@ -1,4 +1,5 @@
 """Support for TPLink lights."""
+import asyncio
 from datetime import timedelta
 import logging
 import time
@@ -25,7 +26,6 @@ from homeassistant.util.color import (
 import homeassistant.util.dt as dt_util
 
 from . import CONF_LIGHT, DOMAIN as TPLINK_DOMAIN
-from .common import async_add_entities_retry
 
 PARALLEL_UPDATES = 0
 SCAN_INTERVAL = timedelta(seconds=5)
@@ -54,23 +54,26 @@ LIGHT_SYSINFO_IS_DIMMABLE = "is_dimmable"
 LIGHT_SYSINFO_IS_VARIABLE_COLOR_TEMP = "is_variable_color_temp"
 LIGHT_SYSINFO_IS_COLOR = "is_color"
 
+MAX_ATTEMPTS = 300
+SLEEP_TIME = 2
+
 
 async def async_setup_entry(hass: HomeAssistantType, config_entry, async_add_entities):
-    """Set up switches."""
+    """Set up lights."""
-    await async_add_entities_retry(
+    devices = hass.data[TPLINK_DOMAIN][CONF_LIGHT]
-        hass, async_add_entities, hass.data[TPLINK_DOMAIN][CONF_LIGHT], add_entity
+    entities = []
-    )
+
-    return True
+    await hass.async_add_executor_job(get_devices_sysinfo, devices)
+    for device in devices:
+        entities.append(TPLinkSmartBulb(device))
+
+    async_add_entities(entities, update_before_add=True)
 
 
-def add_entity(device: SmartBulb, async_add_entities):
+def get_devices_sysinfo(devices):
-    """Check if device is online and add the entity."""
+    """Get sysinfo for all devices."""
-    # Attempt to get the sysinfo. If it fails, it will raise an
+    for device in devices:
-    # exception that is caught by async_add_entities_retry which
+        device.get_sysinfo()
-    # will try again later.
-    device.get_sysinfo()
-
-    async_add_entities([TPLinkSmartBulb(device)], update_before_add=True)
 
 
 def brightness_to_percentage(byt):
@@ -134,6 +137,9 @@ class TPLinkSmartBulb(LightEntity):
         self._last_historical_power_update = None
         self._emeter_params = {}
 
+        self._host = None
+        self._alias = None
+
     @property
     def unique_id(self):
         """Return a unique ID."""
@@ -235,40 +241,36 @@ class TPLinkSmartBulb(LightEntity):
         """Return True if device is on."""
         return self._light_state.state
 
-    def update(self):
+    def attempt_update(self, update_attempt):
-        """Update the TP-Link Bulb's state."""
+        """Attempt to get details the TP-Link bulb."""
         # State is currently being set, ignore.
         if self._is_setting_light_state:
-            return
+            return False
 
         try:
-            # Update light features only once.
             if not self._light_features:
-                self._light_features = self._get_light_features_retry()
+                self._light_features = self._get_light_features()
-            self._light_state = self._get_light_state_retry()
+                self._alias = self._light_features.alias
-            self._is_available = True
+                self._host = self.smartbulb.host
+            self._light_state = self._get_light_state()
+            return True
+
         except (SmartDeviceException, OSError) as ex:
-            if self._is_available:
+            if update_attempt == 0:
-                _LOGGER.warning(
+                _LOGGER.debug(
-                    "Could not read data for %s: %s", self.smartbulb.host, ex
+                    "Retrying in %s seconds for %s|%s due to: %s",
+                    SLEEP_TIME,
+                    self._host,
+                    self._alias,
+                    ex,
                 )
-            self._is_available = False
+            return False
 
     @property
     def supported_features(self):
         """Flag supported features."""
         return self._light_features.supported_features
 
-    def _get_light_features_retry(self) -> LightFeatures:
-        """Retry the retrieval of the supported features."""
-        try:
-            return self._get_light_features()
-        except (SmartDeviceException, OSError):
-            pass
-
-        _LOGGER.debug("Retrying getting light features")
-        return self._get_light_features()
-
     def _get_light_features(self):
         """Determine all supported features in one go."""
         sysinfo = self.smartbulb.sys_info
@@ -304,16 +306,6 @@ class TPLinkSmartBulb(LightEntity):
             has_emeter=has_emeter,
         )
 
-    def _get_light_state_retry(self) -> LightState:
-        """Retry the retrieval of getting light states."""
-        try:
-            return self._get_light_state()
-        except (SmartDeviceException, OSError):
-            pass
-
-        _LOGGER.debug("Retrying getting light state")
-        return self._get_light_state()
-
     def _light_state_from_params(self, light_state_params) -> LightState:
         brightness = None
         color_temp = None
@@ -474,6 +466,33 @@ class TPLinkSmartBulb(LightEntity):
 
         return self._get_device_state()
 
+    async def async_update(self):
+        """Update the TP-Link bulb's state."""
+        for update_attempt in range(MAX_ATTEMPTS):
+            is_ready = await self.hass.async_add_executor_job(
+                self.attempt_update, update_attempt
+            )
+
+            if is_ready:
+                self._is_available = True
+                if update_attempt > 0:
+                    _LOGGER.debug(
+                        "Device %s|%s responded after %s attempts",
+                        self._host,
+                        self._alias,
+                        update_attempt,
+                    )
+                break
+            await asyncio.sleep(SLEEP_TIME)
+        else:
+            if self._is_available:
+                _LOGGER.warning(
+                    "Could not read state for %s|%s",
+                    self._host,
+                    self._alias,
+                )
+            self._is_available = False
+
 
 def _light_state_diff(old_light_state: LightState, new_light_state: LightState):
     old_state_param = old_light_state.to_param()

homeassistant/components/tplink/manifest.json

@@ -3,6 +3,11 @@
   "name": "TP-Link Kasa Smart",
   "config_flow": true,
   "documentation": "https://www.home-assistant.io/integrations/tplink",
-  "requirements": ["pyHS100==0.3.5.1"],
+  "requirements": [
-  "codeowners": ["@rytilahti"]
+    "pyHS100==0.3.5.1"
-}
+  ],
+  "codeowners": [
+    "@rytilahti",
+    "@thegardenmonkey"
+  ]
+}

homeassistant/components/tplink/switch.py

@@ -1,4 +1,5 @@
 """Support for TPLink HS100/HS110/HS200 smart switch."""
+import asyncio
 import logging
 import time
 
@@ -14,7 +15,6 @@ import homeassistant.helpers.device_registry as dr
 from homeassistant.helpers.typing import HomeAssistantType
 
 from . import CONF_SWITCH, DOMAIN as TPLINK_DOMAIN
-from .common import async_add_entities_retry
 
 PARALLEL_UPDATES = 0
 
@@ -23,24 +23,26 @@ _LOGGER = logging.getLogger(__name__)
 ATTR_TOTAL_ENERGY_KWH = "total_energy_kwh"
 ATTR_CURRENT_A = "current_a"
 
-
+MAX_ATTEMPTS = 300
-def add_entity(device: SmartPlug, async_add_entities):
+SLEEP_TIME = 2
-    """Check if device is online and add the entity."""
-    # Attempt to get the sysinfo. If it fails, it will raise an
-    # exception that is caught by async_add_entities_retry which
-    # will try again later.
-    device.get_sysinfo()
-
-    async_add_entities([SmartPlugSwitch(device)], update_before_add=True)
 
 
 async def async_setup_entry(hass: HomeAssistantType, config_entry, async_add_entities):
     """Set up switches."""
-    await async_add_entities_retry(
+    devices = hass.data[TPLINK_DOMAIN][CONF_SWITCH]
-        hass, async_add_entities, hass.data[TPLINK_DOMAIN][CONF_SWITCH], add_entity
+    entities = []
-    )
 
-    return True
+    await hass.async_add_executor_job(get_devices_sysinfo, devices)
+    for device in devices:
+        entities.append(SmartPlugSwitch(device))
+
+    async_add_entities(entities, update_before_add=True)
+
+
+def get_devices_sysinfo(devices):
+    """Get sysinfo for all devices."""
+    for device in devices:
+        device.get_sysinfo()
 
 
 class SmartPlugSwitch(SwitchEntity):
@@ -51,7 +53,7 @@ class SmartPlugSwitch(SwitchEntity):
         self.smartplug = smartplug
         self._sysinfo = None
         self._state = None
-        self._available = False
+        self._is_available = False
         # Set up emeter cache
         self._emeter_params = {}
 
@@ -59,6 +61,7 @@ class SmartPlugSwitch(SwitchEntity):
         self._alias = None
         self._model = None
         self._device_id = None
+        self._host = None
 
     @property
     def unique_id(self):
@@ -84,7 +87,7 @@ class SmartPlugSwitch(SwitchEntity):
     @property
     def available(self) -> bool:
         """Return if switch is available."""
-        return self._available
+        return self._is_available
 
     @property
     def is_on(self):
@@ -110,24 +113,29 @@ class SmartPlugSwitch(SwitchEntity):
         children = self.smartplug.sys_info["children"]
         return next(c for c in children if c["id"] == self.smartplug.context)
 
-    def update(self):
+    def update_state(self):
         """Update the TP-Link switch's state."""
+        if self.smartplug.context is None:
+            self._state = self.smartplug.state == self.smartplug.SWITCH_STATE_ON
+        else:
+            self._state = self._plug_from_context["state"] == 1
+
+    def attempt_update(self, update_attempt):
+        """Attempt to get details from the TP-Link switch."""
         try:
             if not self._sysinfo:
                 self._sysinfo = self.smartplug.sys_info
-                self._mac = self.smartplug.mac
+                self._mac = self._sysinfo["mac"]
-                self._model = self.smartplug.model
+                self._model = self._sysinfo["model"]
+                self._host = self.smartplug.host
                 if self.smartplug.context is None:
-                    self._alias = self.smartplug.alias
+                    self._alias = self._sysinfo["alias"]
                     self._device_id = self._mac
                 else:
                     self._alias = self._plug_from_context["alias"]
                     self._device_id = self.smartplug.context
 
-            if self.smartplug.context is None:
+            self.update_state()
-                self._state = self.smartplug.state == self.smartplug.SWITCH_STATE_ON
-            else:
-                self._state = self._plug_from_context["state"] == 1
 
             if self.smartplug.has_emeter:
                 emeter_readings = self.smartplug.get_emeter_realtime()
@@ -153,12 +161,40 @@ class SmartPlugSwitch(SwitchEntity):
                 except KeyError:
                     # Device returned no daily history
                     pass
-
+            return True
-            self._available = True
-
         except (SmartDeviceException, OSError) as ex:
-            if self._available:
+            if update_attempt == 0:
-                _LOGGER.warning(
+                _LOGGER.debug(
-                    "Could not read state for %s: %s", self.smartplug.host, ex
+                    "Retrying in %s seconds for %s|%s due to: %s",
+                    SLEEP_TIME,
+                    self._host,
+                    self._alias,
+                    ex,
                 )
-            self._available = False
+            return False
+
+    async def async_update(self):
+        """Update the TP-Link switch's state."""
+        for update_attempt in range(MAX_ATTEMPTS):
+            is_ready = await self.hass.async_add_executor_job(
+                self.attempt_update, update_attempt
+            )
+
+            if is_ready:
+                self._is_available = True
+                if update_attempt > 0:
+                    _LOGGER.debug(
+                        "Device %s|%s responded after %s attempts",
+                        self._host,
+                        self._alias,
+                        update_attempt,
+                    )
+                break
+            await asyncio.sleep(SLEEP_TIME)
+
+        else:
+            if self._is_available:
+                _LOGGER.warning(
+                    "Could not read state for %s|%s", self.smartplug.host, self._alias
+                )
+            self._is_available = False

tests/components/tplink/test_common.py

@@ -1,82 +0,0 @@
-"""Common code tests."""
-from datetime import timedelta
-
-from pyHS100 import SmartDeviceException
-
-from homeassistant.components.tplink.common import async_add_entities_retry
-from homeassistant.helpers.typing import HomeAssistantType
-
-from tests.async_mock import MagicMock
-
-
-async def test_async_add_entities_retry(hass: HomeAssistantType):
-    """Test interval callback."""
-    async_add_entities_callback = MagicMock()
-
-    # The objects that will be passed to async_add_entities_callback.
-    objects = ["Object 1", "Object 2", "Object 3", "Object 4"]
-
-    # For each call to async_add_entities_callback, the following side effects
-    # will be triggered in order. This set of side effects accurateley simulates
-    # 3 attempts to add all entities while also handling several return types.
-    # To help understand what's going on, a comment exists describing what the
-    # object list looks like throughout the iterations.
-    callback_side_effects = [
-        # OB1, OB2, OB3, OB4
-        False,
-        False,
-        True,  # Object 3
-        False,
-        # OB1, OB2, OB4
-        True,  # Object 1
-        SmartDeviceException("My error"),
-        False,
-        # OB2, OB4
-        True,  # Object 2
-        True,  # Object 4
-    ]
-
-    callback = MagicMock(side_effect=callback_side_effects)
-
-    await async_add_entities_retry(
-        hass,
-        async_add_entities_callback,
-        objects,
-        callback,
-        interval=timedelta(milliseconds=100),
-    )
-    await hass.async_block_till_done()
-
-    assert callback.call_count == len(callback_side_effects)
-
-
-async def test_async_add_entities_retry_cancel(hass: HomeAssistantType):
-    """Test interval callback."""
-    async_add_entities_callback = MagicMock()
-
-    callback_side_effects = [
-        False,
-        False,
-        True,  # Object 1
-        False,
-        True,  # Object 2
-        SmartDeviceException("My error"),
-        False,
-        True,  # Object 3
-        True,  # Object 4
-    ]
-
-    callback = MagicMock(side_effect=callback_side_effects)
-
-    objects = ["Object 1", "Object 2", "Object 3", "Object 4"]
-    cancel = await async_add_entities_retry(
-        hass,
-        async_add_entities_callback,
-        objects,
-        callback,
-        interval=timedelta(milliseconds=100),
-    )
-    cancel()
-    await hass.async_block_till_done()
-
-    assert callback.call_count == 4

tests/components/tplink/test_light.py

@@ -1,4 +1,5 @@
 """Tests for light platform."""
+import logging
 from typing import Callable, NamedTuple
 
 from pyHS100 import SmartDeviceException
@@ -20,6 +21,7 @@ from homeassistant.components.tplink.common import (
     CONF_DISCOVERY,
     CONF_LIGHT,
 )
+from homeassistant.components.tplink.light import SLEEP_TIME
 from homeassistant.const import (
     ATTR_ENTITY_ID,
     CONF_HOST,
@@ -474,20 +476,6 @@ async def test_get_light_state_retry(
 
     light_mock_data.get_sysinfo_mock.side_effect = get_sysinfo_side_effect
 
-    # Setup test for retries of getting state information.
-    get_state_call_count = 0
-
-    def get_light_state_side_effect():
-        nonlocal get_state_call_count
-        get_state_call_count += 1
-
-        if get_state_call_count == 1:
-            raise SmartDeviceException()
-
-        return light_mock_data.light_state
-
-    light_mock_data.get_light_state_mock.side_effect = get_light_state_side_effect
-
     # Setup test for retries of setting state information.
     set_state_call_count = 0
 
@@ -534,3 +522,58 @@ async def test_get_light_state_retry(
     assert light_mock_data.get_sysinfo_mock.call_count < 40
     assert light_mock_data.get_light_state_mock.call_count < 40
     assert light_mock_data.set_light_state_mock.call_count < 10
+
+
+async def test_update_failure(
+    hass: HomeAssistant, light_mock_data: LightMockData, caplog
+):
+    """Test that update failures are logged."""
+
+    await async_setup_component(hass, HA_DOMAIN, {})
+    await hass.async_block_till_done()
+
+    await async_setup_component(
+        hass,
+        tplink.DOMAIN,
+        {
+            tplink.DOMAIN: {
+                CONF_DISCOVERY: False,
+                CONF_LIGHT: [{CONF_HOST: "123.123.123.123"}],
+            }
+        },
+    )
+    await hass.async_block_till_done()
+    caplog.clear()
+    caplog.set_level(logging.WARNING)
+    await hass.helpers.entity_component.async_update_entity("light.light1")
+    assert caplog.text == ""
+
+    with patch("homeassistant.components.tplink.light.MAX_ATTEMPTS", 0):
+        caplog.clear()
+        caplog.set_level(logging.WARNING)
+        await hass.helpers.entity_component.async_update_entity("light.light1")
+        assert "Could not read state for 123.123.123.123|light1" in caplog.text
+
+    get_state_call_count = 0
+
+    def get_light_state_side_effect():
+        nonlocal get_state_call_count
+        get_state_call_count += 1
+
+        if get_state_call_count == 1:
+            raise SmartDeviceException()
+
+        return light_mock_data.light_state
+
+    light_mock_data.get_light_state_mock.side_effect = get_light_state_side_effect
+
+    with patch("homeassistant.components.tplink.light", MAX_ATTEMPTS=2, SLEEP_TIME=0):
+        caplog.clear()
+        caplog.set_level(logging.DEBUG)
+
+        await update_entity(hass, "light.light1")
+        assert (
+            f"Retrying in {SLEEP_TIME} seconds for 123.123.123.123|light1"
+            in caplog.text
+        )
+        assert "Device 123.123.123.123|light1 responded after " in caplog.text