Reduce keep-alive warning logs when the controlled entity becomes unavailable

[pdcastro]

Recently I powered off a heating appliance for the summer months (it will be used again when the weather gets colder). The appliance has a MQTT switch controlled by Versatile Thermostat using a thermostat-over-switch configuration with a short keep-alive period of 15 seconds. As a result of powering it off, the Home Assistant logs got flooded with the following warning messages, logged every 15 seconds:

2024-06-23 02:23:05.810 WARNING (MainThread) [homeassistant.helpers.service] Referenced entities switch.my_switch are missing or not currently available
2024-06-23 02:23:20.813 WARNING (MainThread) [homeassistant.helpers.service] Referenced entities switch.my_switch are missing or not currently available
2024-06-23 02:23:35.816 WARNING (MainThread) [homeassistant.helpers.service] Referenced entities switch.my_switch are missing or not currently available
...

These log messages are printed by Home Assistant Core (not Versatile Thermostat directly) when Versatile Thermostat uses a Home Assistant service to request the underlying switch to be turned on or off.

These log messages are relevant and informative, but not if they flood the logs. This PR proposes a solution that consists of testing whether the underlying switch entity is available before the keep-alive feature makes a call to the turn on or turn off services. If it is unavailable, VTherm itself prints a warning message, but not too often, by using a backoff timer: After a warning message is logged, the next message is logged no sooner than 30 seconds, then 60s, 120s, 240s... capped at 86400s = 24h. This way, if the controlled switched is unavailable for 3 months of summer, the warning message will be printed a moderate number of times on the first day, then only once a day from the second day onwards. (This starts again when HASS is restarted, but I think that’s OK.) Example:

2024-06-25 16:17:39.618 WARNING (MainThread) [custom_components.versatile_thermostat.underlyings] Entity switch.my_switch is unavailable (state: None). Will keep trying keep alive calls, but won't log this condition every time.
2024-06-25 16:18:09.621 WARNING (MainThread) [custom_components.versatile_thermostat.underlyings] Entity switch.my_switch is unavailable (state: None). Will keep trying keep alive calls, but won't log this condition every time.
2024-06-25 16:19:09.626 WARNING (MainThread) [custom_components.versatile_thermostat.underlyings] Entity switch.my_switch is unavailable (state: None). Will keep trying keep alive calls, but won't log this condition every time.
...

[jmcollin78]

@pdcastro can you give a try to the main branch on your local environment please? If ok I will do a release soon

[pdcastro]

Thanks @jmcollin78 👍 VTherm’s main branch is at the moment identical to this PR’s branch (git diff is empty, my commit is the only addition since VTherm release 6.2.5), so I have already successfully tested it:

...
2024-06-28 01:09:16.554 WARNING (MainThread) [custom_components.versatile_thermostat.underlyings] Entity switch.my_switch is not available (state: None). Will keep trying keep alive calls, but won't log this condition every time.
2024-06-28 09:41:19.014 WARNING (MainThread) [custom_components.versatile_thermostat.underlyings] Entity switch.my_switch is not available (state: None). Will keep trying keep alive calls, but won't log this condition every time.
2024-06-28 10:57:04.350 WARNING (MainThread) [custom_components.versatile_thermostat.underlyings] Entity switch.my_switch has recovered (state: off).

Note how the last log message above also exercises the “Entity has recovered (state: off)” execution path, and the controlled appliance works fine. 🎉

[jmcollin78]

https://github.com/jmcollin78/versatile_thermostat/releases/tag/6.2.6