Stopping override can be interrupted by other events

[iainlane]

Same symptom as #24 (heating stays on when no thermostats want it) but a different cause. See this log (extra debugging added by me previously):

2024-01-29 13:20:01.163 DEBUG (MainThread) [custom_components.zoned_heating.switch] Zone climate.spare_room_trv_e1 updated: action=idle
2024-01-29 13:20:01.163 DEBUG (MainThread) [custom_components.zoned_heating.switch] Updated override temperature_increase=0, override_active=False
2024-01-29 13:20:01.164 DEBUG (MainThread) [custom_components.zoned_heating.switch] Stopping override mode and restoring previous settings. self._stored_controller_state=heat, self._stored_controller_setpoint=10.0, current_state[ATTR_HVAC_MODE]=on, current_state[ATTR_TEMPERATURE]=None
2024-01-29 13:20:01.164 DEBUG (MainThread) [custom_components.zoned_heating.util] setting hvac mode to heat for climate.thermostat
2024-01-29 13:20:01.165 DEBUG (MainThread) [custom_components.better_thermostat.events.trv] better_thermostat Spare Room: TRV climate.spare_room_trv_e1 update received
2024-01-29 13:20:01.165 DEBUG (MainThread) [custom_components.better_thermostat.events.trv] better_thermostat Spare Room: TRV climate.spare_room_trv_e1 sends new internal temperature from 19.6 to 20.6
2024-01-29 13:20:01.165 DEBUG (MainThread) [custom_components.better_thermostat.events.trv] better_thermostat Spare Room: trigger_trv_change / _old_heating_setpoint: 20.5 - _new_heating_setpoint: 20.5 - _last_temperature: 20.5
2024-01-29 13:20:01.166 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/mynest:executeCommand
2024-01-29 13:20:01.166 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.ThermostatMode.SetMode', 'params': {'mode': 'HEAT'}}
2024-01-29 13:20:01.167 DEBUG (MainThread) [custom_components.better_thermostat.utils.helpers] better_thermostat Spare Room: climate.spare_room_trv_e1 / heating_power_valve_position - temp diff: 0.1 - heating power: 0.01 - expected valve position: 10%
2024-01-29 13:20:01.167 DEBUG (MainThread) [custom_components.better_thermostat.utils.controlling] better_thermostat Spare Room: TO TRV set_temperature: climate.spare_room_trv_e1 from: 20.5 to: 21.5
2024-01-29 13:20:01.172 DEBUG (MainThread) [custom_components.better_thermostat.utils.controlling] better_thermostat Spare Room: climate.spare_room_trv_e1 / check_target_temp / _last: 21.5 - _current: 20.5
2024-01-29 13:20:02.495 DEBUG (MainThread) [custom_components.zoned_heating.switch] Zone climate.spare_room_trv_e1 updated: setpoint=21.5
2024-01-29 13:20:02.495 DEBUG (MainThread) [custom_components.zoned_heating.switch] Updated override temperature_increase=0.9, override_active=True
2024-01-29 13:20:02.495 DEBUG (MainThread) [custom_components.zoned_heating.switch] Storing controller state={'temperature': 16.5, 'current_temperature': 15.8, 'hvac_action': <HVACAction.HEATING: 'heating'>, 'hvac_mode': 'heat'}
2024-01-29 13:20:02.495 DEBUG (MainThread) [custom_components.zoned_heating.switch] Updating override setpoint=16.5
2024-01-29 13:20:02.495 DEBUG (MainThread) [custom_components.zoned_heating.switch] start ignoring controller state changes
2024-01-29 13:20:02.495 DEBUG (MainThread) [custom_components.zoned_heating.util] setting temperature to 16.5 for climate.thermostat
2024-01-29 13:20:02.497 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/mynest:executeCommand
2024-01-29 13:20:02.497 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.ThermostatTemperatureSetpoint.SetHeat', 'params': {'heatCelsius': 16.5}}
2024-01-29 13:20:03.019 DEBUG (MainThread) [custom_components.zoned_heating.util] setting temperature to 16.5 for climate.thermostat
2024-01-29 13:20:03.020 DEBUG (MainThread) [google_nest_sdm.auth] request[post]=https://smartdevicemanagement.googleapis.com/v1/enterprises/mynest:executeCommand
2024-01-29 13:20:03.021 DEBUG (MainThread) [google_nest_sdm.auth] request[post json]={'command': 'sdm.devices.commands.ThermostatTemperatureSetpoint.SetHeat', 'params': {'heatCelsius': 16.5}}
2024-01-29 13:20:03.597 DEBUG (MainThread) [custom_components.zoned_heating.switch] Zone climate.hallway_trv_e1 updated: setpoint=11.0
2024-01-29 13:20:03.598 DEBUG (MainThread) [custom_components.zoned_heating.switch] Override not changed, nothing to do. self.override_active=True, override_active=True, self.temperature_increase=0.9, temperature_increase=0.9
2024-01-29 13:20:04.258 DEBUG (MainThread) [custom_components.zoned_heating.switch] Zone climate.spare_room_trv_e1 updated: action=heating
2024-01-29 13:20:04.258 DEBUG (MainThread) [custom_components.zoned_heating.switch] Override not changed, nothing to do. self.override_active=True, override_active=True, self.temperature_increase=0.9, temperature_increase=0.9
2024-01-29 13:20:04.773 DEBUG (MainThread) [custom_components.zoned_heating.switch] Forgetting stored controller state
2024-01-29 13:20:04.773 DEBUG (MainThread) [custom_components.zoned_heating.switch] Stopped override mode

What seems to have happened was this

• The last TRV went idle
• We started to restore (turn off) the system. We ran this to change the mode, but we did not get this far before...
• At the same time another TRV started to want heat
• We handled this request straight away
• This was considered to be us starting override mode, and so we stored the current settings of the thermostat, which was still the previous overridden temperature, since the stop action had not finished.

You can see setting temperature to 16.5 for climate.thermostat twice in the log. I think one of them must be the delayed/awaited stop call and one must be the new override.

Hope that makes sense. Seems like a problem caused by async/threads. Not sure right now how best to fix it ...