Reduce keep-alive warning logs when the controlled entity becomes unavailable (#476)

custom_components/versatile_thermostat/keep_alive.py

@@ -10,6 +10,7 @@ the keep_alive setting of Home Assistant's Generic Thermostat integration:
 import logging
 from collections.abc import Awaitable, Callable
 from datetime import timedelta, datetime
+from time import monotonic
 
 from homeassistant.core import HomeAssistant, CALLBACK_TYPE
 from homeassistant.helpers.event import async_track_time_interval
@@ -18,6 +19,79 @@ from homeassistant.helpers.event import async_track_time_interval
 _LOGGER = logging.getLogger(__name__)
 
 
+class BackoffTimer:
+    """Exponential backoff timer with a non-blocking polling-style implementation.
+
+    Usage example:
+        timer = BackoffTimer(multiplier=1.5, upper_limit_sec=600)
+        while some_condition:
+            if timer.is_ready():
+                do_something()
+    """
+
+    def __init__(
+        self,
+        *,
+        multiplier=2.0,
+        lower_limit_sec=30,
+        upper_limit_sec=86400,
+        initially_ready=True,
+    ):
+        """Initialize a BackoffTimer instance.
+
+        Args:
+            multiplier (int, optional): Period multiplier applied when is_ready() is True.
+            lower_limit_sec (int, optional): Initial backoff period in seconds.
+            upper_limit_sec (int, optional): Maximum backoff period in seconds.
+            initially_ready (bool, optional): Whether is_ready() should return True the
+            first time it is called, or after a call to reset().
+        """
+        self._multiplier = multiplier
+        self._lower_limit_sec = lower_limit_sec
+        self._upper_limit_sec = upper_limit_sec
+        self._initially_ready = initially_ready
+
+        self._timestamp = 0
+        self._period_sec = self._lower_limit_sec
+
+    @property
+    def in_progress(self) -> bool:
+        """Whether the backoff timer is in progress (True after a call to is_ready())."""
+        return bool(self._timestamp)
+
+    def reset(self):
+        """Reset a BackoffTimer instance."""
+        self._timestamp = 0
+        self._period_sec = self._lower_limit_sec
+
+    def is_ready(self) -> bool:
+        """Check whether an exponentially increasing period of time has passed.
+
+        Whenever is_ready() returns True, the timer period is multiplied so that
+        it takes longer until is_ready() returns True again.
+        Returns:
+            bool: True if enough time has passed since one of the following events,
+            in relation to an instance of this class:
+            - The last time when this method returned True, if it ever did.
+            - Or else, when this method was first called after a call to reset().
+            - Or else, when this method was first called.
+            False otherwise.
+        """
+        now = monotonic()
+        if self._timestamp == 0:
+            self._timestamp = now
+            return self._initially_ready
+        elif now - self._timestamp >= self._period_sec:
+            self._timestamp = now
+            self._period_sec = max(
+                self._lower_limit_sec,
+                min(self._upper_limit_sec, self._period_sec * self._multiplier),
+            )
+            return True
+
+        return False
+
+
 class IntervalCaller:
     """Repeatedly call a given async action function at a given regular interval.
 
@@ -28,6 +102,7 @@ class IntervalCaller:
         self._hass = hass
         self._interval_sec = interval_sec
         self._remove_handle: CALLBACK_TYPE | None = None
+        self.backoff_timer = BackoffTimer()
 
     @property
     def interval_sec(self) -> float:

custom_components/versatile_thermostat/underlyings.py

@@ -5,7 +5,7 @@ import logging
 from typing import Any
 from enum import StrEnum
 
-from homeassistant.const import ATTR_ENTITY_ID, STATE_ON, UnitOfTemperature
+from homeassistant.const import ATTR_ENTITY_ID, STATE_ON, STATE_UNAVAILABLE
 from homeassistant.core import State
 
 from homeassistant.exceptions import ServiceNotFound
@@ -253,7 +253,28 @@ class UnderlyingSwitch(UnderlyingEntity):
 
     async def _keep_alive_callback(self):
         """Keep alive: Turn on if already turned on, turn off if already turned off."""
-        await (self.turn_on() if self.is_device_active else self.turn_off())
+        timer = self._keep_alive.backoff_timer
+        state: State | None = self._hass.states.get(self._entity_id)
+        # Normal, expected state.state values are "on" and "off". An absent
+        # underlying MQTT switch was observed to produce either state == None
+        # or state.state == STATE_UNAVAILABLE ("unavailable").
+        if state is None or state.state == STATE_UNAVAILABLE:
+            if timer.is_ready():
+                _LOGGER.warning(
+                    "Entity %s is not available (state: %s). Will keep trying "
+                    "keep alive calls, but won't log this condition every time.",
+                    self._entity_id,
+                    state.state if state else "None",
+                )
+        else:
+            if timer.in_progress:
+                timer.reset()
+                _LOGGER.warning(
+                    "Entity %s has recovered (state: %s).",
+                    self._entity_id,
+                    state.state,
+                )
+            await (self.turn_on() if self.is_device_active else self.turn_off())
 
     # @overrides this breaks some unit tests TypeError: object MagicMock can't be used in 'await' expression
     async def turn_off(self):

tests/test_switch_keep_alive.py

@@ -6,6 +6,7 @@ from unittest.mock import ANY, _Call, call, patch
 from datetime import datetime, timedelta
 from typing import cast
 
+from custom_components.versatile_thermostat.keep_alive import BackoffTimer
 from custom_components.versatile_thermostat.thermostat_switch import (
     ThermostatOverSwitch,
 )
@@ -52,6 +53,7 @@ class CommonMocks:
     hass: HomeAssistant
     thermostat: ThermostatOverSwitch
     mock_is_state: MagicMock
+    mock_get_state: MagicMock
     mock_service_call: MagicMock
     mock_async_track_time_interval: MagicMock
     mock_send_event: MagicMock
@@ -73,15 +75,18 @@ async def common_mocks(
         thermostat = cast(ThermostatOverSwitch, await create_thermostat(
             hass, config_entry, "climate.theoverswitchmockname"
         ))
-        yield CommonMocks(
+        with patch("homeassistant.core.StateMachine.get") as mock_get_state:
-            config_entry=config_entry,
+            mock_get_state.return_value.state = "off"
-            hass=hass,
+            yield CommonMocks(
-            thermostat=thermostat,
+                config_entry=config_entry,
-            mock_is_state=mock_is_state,
+                hass=hass,
-            mock_service_call=mock_service_call,
+                thermostat=thermostat,
-            mock_async_track_time_interval=mock_async_track_time_interval,
+                mock_is_state=mock_is_state,
-            mock_send_event=mock_send_event,
+                mock_get_state=mock_get_state,
-        )
+                mock_service_call=mock_service_call,
+                mock_async_track_time_interval=mock_async_track_time_interval,
+                mock_send_event=mock_send_event,
+            )
         # Clean the entity
         thermostat.remove_thermostat()
 
@@ -256,3 +261,123 @@ class TestKeepAlive:
                 call("switch", SERVICE_TURN_OFF, {"entity_id": "switch.mock_switch"}),
             ],
         )
+
+
+class TestBackoffTimer:
+    """Test the keep_alive.BackoffTimer helper class."""
+
+    def test_exponential_period_increase(self):
+        """Test that consecutive calls to is_ready() produce increasing wait periods."""
+        with patch(
+            "custom_components.versatile_thermostat.keep_alive.monotonic"
+        ) as mock_monotonic:
+            timer = BackoffTimer(
+                multiplier=2,
+                lower_limit_sec=30,
+                upper_limit_sec=86400,
+                initially_ready=True,
+            )
+            mock_monotonic.return_value = 100
+            assert timer.is_ready()
+            mock_monotonic.return_value = 129
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 130
+            assert timer.is_ready()
+            mock_monotonic.return_value = 188
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 189
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 190
+            assert timer.is_ready()
+            mock_monotonic.return_value = 309
+            assert not timer.is_ready()
+
+    def test_the_upper_limit_option(self):
+        """Test the timer.in_progress property and the effect of timer.reset()."""
+        with patch(
+            "custom_components.versatile_thermostat.keep_alive.monotonic"
+        ) as mock_monotonic:
+            timer = BackoffTimer(
+                multiplier=2,
+                lower_limit_sec=30,
+                upper_limit_sec=50,
+                initially_ready=True,
+            )
+            mock_monotonic.return_value = 100
+            assert timer.is_ready()
+            mock_monotonic.return_value = 129
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 130
+            assert timer.is_ready()
+            mock_monotonic.return_value = 178
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 179
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 180
+            assert timer.is_ready()
+            mock_monotonic.return_value = 229
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 230
+            assert timer.is_ready()
+
+    def test_the_lower_limit_option(self):
+        """Test the timer.in_progress property and the effect of timer.reset()."""
+        with patch(
+            "custom_components.versatile_thermostat.keep_alive.monotonic"
+        ) as mock_monotonic:
+            timer = BackoffTimer(
+                multiplier=0.5,
+                lower_limit_sec=30,
+                upper_limit_sec=50,
+                initially_ready=True,
+            )
+            mock_monotonic.return_value = 100
+            assert timer.is_ready()
+            mock_monotonic.return_value = 129
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 130
+            assert timer.is_ready()
+            mock_monotonic.return_value = 158
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 159
+            assert not timer.is_ready()
+            mock_monotonic.return_value = 160
+            assert timer.is_ready()
+
+    def test_initial_is_ready_result(self):
+        """Test that the first call to is_ready() produces the initially_ready option value."""
+        with patch(
+            "custom_components.versatile_thermostat.keep_alive.monotonic"
+        ) as mock_monotonic:
+            for initial in [True, False]:
+                timer = BackoffTimer(
+                    multiplier=2,
+                    lower_limit_sec=30,
+                    upper_limit_sec=86400,
+                    initially_ready=initial,
+                )
+                mock_monotonic.return_value = 100
+                assert timer.is_ready() == initial
+                assert not timer.is_ready()
+
+    def test_in_progress_and_reset(self):
+        """Test the timer.in_progress property and the effect of timer.reset()."""
+        with patch(
+            "custom_components.versatile_thermostat.keep_alive.monotonic"
+        ) as mock_monotonic:
+            timer = BackoffTimer(
+                multiplier=2,
+                lower_limit_sec=30,
+                upper_limit_sec=86400,
+                initially_ready=True,
+            )
+            mock_monotonic.return_value = 100
+            assert not timer.in_progress
+            assert timer.is_ready()
+            assert timer.in_progress
+            assert not timer.is_ready()
+            timer.reset()
+            assert not timer.in_progress
+            assert timer.is_ready()
+            assert timer.in_progress
+            assert not timer.is_ready()