From 864e904e21187e204361c8dbd253521cf0249554 Mon Sep 17 00:00:00 2001 From: Paulo Ferreira de Castro Date: Fri, 28 Jun 2024 08:53:40 +0100 Subject: [PATCH] Reduce keep-alive warning logs when the controlled entity becomes unavailable (#476) --- .../versatile_thermostat/keep_alive.py | 75 +++++++++ .../versatile_thermostat/underlyings.py | 25 ++- tests/test_switch_keep_alive.py | 143 ++++++++++++++++-- 3 files changed, 232 insertions(+), 11 deletions(-) diff --git a/custom_components/versatile_thermostat/keep_alive.py b/custom_components/versatile_thermostat/keep_alive.py index 1457cdf..e5fdc68 100644 --- a/custom_components/versatile_thermostat/keep_alive.py +++ b/custom_components/versatile_thermostat/keep_alive.py @@ -10,6 +10,7 @@ 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 @@ _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 @@ def __init__(self, hass: HomeAssistant, interval_sec: float) -> None: 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: diff --git a/custom_components/versatile_thermostat/underlyings.py b/custom_components/versatile_thermostat/underlyings.py index 4112e2c..f1ae0e4 100644 --- a/custom_components/versatile_thermostat/underlyings.py +++ b/custom_components/versatile_thermostat/underlyings.py @@ -5,7 +5,7 @@ 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 @@ def is_device_active(self): 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): diff --git a/tests/test_switch_keep_alive.py b/tests/test_switch_keep_alive.py index a6c9336..c8dc846 100644 --- a/tests/test_switch_keep_alive.py +++ b/tests/test_switch_keep_alive.py @@ -6,6 +6,7 @@ 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( - config_entry=config_entry, - hass=hass, - thermostat=thermostat, - mock_is_state=mock_is_state, - mock_service_call=mock_service_call, - mock_async_track_time_interval=mock_async_track_time_interval, - mock_send_event=mock_send_event, - ) + with patch("homeassistant.core.StateMachine.get") as mock_get_state: + mock_get_state.return_value.state = "off" + yield CommonMocks( + config_entry=config_entry, + hass=hass, + thermostat=thermostat, + mock_is_state=mock_is_state, + 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 @@ async def test_switch_keep_alive(self, common_mocks: CommonMocks): 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()