Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

radiator valve stuck in loop ("changed to heat / turned off / … triggered by service Climate: Set HVAC mode") until HA reboot #121

Closed
maia opened this issue Oct 12, 2023 · 29 comments
Labels
developed When development is done and tested P1 Priority 1

Comments

@maia
Copy link

maia commented Oct 12, 2023

Version of the custom_component

I'm running the latest VTherm version 3.5.2, all other integrations and HA have no available updates either.

Configuration

climate.schlafzimmer_eve_trv (the underlying radiator valve controlled by versatile thermostat):

hvac_modes:
  - 'off'
  - heat
min_temp: 7
max_temp: 35
current_temperature: 19.5
temperature: null
hvac_action: idle
friendly_name: Schlafzimmer Eve TRV
supported_features: 1

climate.schlafzimmer_heizung (the versatile thermostat service):

hvac_modes:
  - 'off'
  - heat
min_temp: 16
max_temp: 26
preset_modes:
  - none
  - eco
  - comfort
  - boost
current_temperature: 21.5
temperature: 17
hvac_action: idle
preset_mode: eco
hvac_mode: 'off'
type: thermostat_over_climate
eco_temp: 19
boost_temp: 21
comfort_temp: 20
eco_away_temp: 17
boost_away_temp: 19
comfort_away_temp: 18
power_temp: null
target_temp: 17
current_temp: 21.5
ext_current_temperature: 12.6000032424927
current_power: null
current_power_max: null
saved_preset_mode: eco
saved_target_temp: 19
saved_hvac_mode: null
window_state: null
motion_state: null
overpowering_state: null
presence_state: 'off'
window_auto_state: false
security_delay_min: 60
security_min_on_percent: 0.5
security_default_on_percent: 0.1
last_temperature_datetime: '2023-10-12T08:57:12.562924+02:00'
last_ext_temperature_datetime: '2023-10-12T08:51:55.650098+02:00'
security_state: false
minimal_activation_delay_sec: 10
device_power: 1
mean_cycle_power: null
total_energy: 0.10959254972222225
last_update_datetime: '2023-10-12T08:57:12.569348+02:00'
timezone: Europe/Vienna
window_delay_sec: 30
window_auto_open_threshold: 0.05
window_auto_close_threshold: 0
window_auto_max_duration: 60
underlying_climate_1: null
underlying_climate_2: null
underlying_climate_3: null
start_hvac_action_date: null
friendly_name: Schlafzimmer Heizung
supported_features: 17

Describe the bug

After creating a Virtual Thermostat for a Eve Thermo Homekit Device and a simple thermostat lovelace card, when switching the preset in the UI the thermostat valve started turning on/off/on/off/on/off as fast as it could, until its battery was nearly empty and I rebooted HA. Other than the reboot of HA I couldn't find anything to stop this loop.

As this happened to me a week ago with a different virtual thermostat, this seems to be a more frequent issue than initially expected, at least in my setup.

Here's everything I could find that might be relevant to debugging the issue. I might be able to reproduce it, it was just a very bad timing when it happened.

Debug log

Logbook of the VTherm device:

Schlafzimmer Heizung  turned off
23:11:50 - 10 hours ago

Schlafzimmer Heizung  changed to Heat
23:11:49 - 10 hours ago

Schlafzimmer Heizung  turned off
23:11:49 - 10 hours ago

Schlafzimmer Heizung  changed to Heat
23:11:49 - 10 hours ago

Schlafzimmer Heizung  turned off
23:11:48 - 10 hours ago

Schlafzimmer Heizung  changed to Heat
23:11:48 - 10 hours ago

Schlafzimmer Heizung  turned off
23:11:47 - 10 hours ago

Schlafzimmer Heizung  changed to Heat
23:11:47 - 10 hours ago

Schlafzimmer Heizung  turned off
23:11:46 - 10 hours ago

Schlafzimmer Heizung  changed to Heat
23:11:46 - 10 hours ago

Schlafzimmer Heizung  turned off
23:11:46 - 10 hours ago

Schlafzimmer Heizung  changed to Heat
23:11:45 - 10 hours ago

Logbook of the underlying Eve Thermo TRV (thermostatic radiator valve):

Schlafzimmer Eve TRV  changed to Heat triggered by service Climate: Set HVAC mode
23:11:56 - 10 hours ago

Schlafzimmer Eve TRV  turned off triggered by service Climate: Set HVAC mode
23:11:56 - 10 hours ago

Schlafzimmer Eve TRV  changed to Heat triggered by service Climate: Set HVAC mode
23:11:55 - 10 hours ago

Schlafzimmer Eve TRV  turned off triggered by service Climate: Set HVAC mode
23:11:55 - 10 hours ago

Schlafzimmer Eve TRV  changed to Heat triggered by service Climate: Set HVAC mode
23:11:54 - 10 hours ago

Schlafzimmer Eve TRV  turned off triggered by service Climate: Set HVAC mode
23:11:54 - 10 hours ago

Schlafzimmer Eve TRV  changed to Heat triggered by service Climate: Set HVAC mode
23:11:54 - 10 hours ago

Schlafzimmer Eve TRV  turned off triggered by service Climate: Set HVAC mode
23:11:53 - 10 hours ago

Schlafzimmer Eve TRV  changed to Heat triggered by service Climate: Set HVAC mode
23:11:53 - 10 hours ago

Versatile Thermostat debug log while the TRV turned on and off constantly (I can provide more if necessary):

2023-10-11 23:05:00.323 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Checking new cycle. hvac_mode=off, security_state=False, preset_mode=eco
2023-10-11 23:05:00.323 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - power not configured. check_overpowering not available
2023-10-11 23:05:00.323 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - checking security delta_temp=2.2 delta_ext_temp=2.2 mod_cond=False temp_cond=False climate_cond=False switch_cond=False
2023-10-11 23:05:00.323 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - End of cycle (HVAC_MODE_OFF)
2023-10-11 23:05:00.335 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_security_state - climate state change
2023-10-11 23:05:00.335 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_window_state - climate state change
2023-10-11 23:05:00.335 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_presence_state - climate state change
2023-10-11 23:05:00.335 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_temp_datetime - climate state change
2023-10-11 23:05:00.335 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_ext_temp_datetime - climate state change
2023-10-11 23:05:00.335 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_temperature_slope - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_energy - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_security_state - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_window_state - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_presence_state - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_temp_datetime - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_ext_temp_datetime - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_temperature_slope - climate state change
2023-10-11 23:05:00.336 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_energy - climate state change
2023-10-11 23:05:00.733 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - _async_climate_changed new_state is <state climate.schlafzimmer_eve_trv=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>], min_temp=10.0, max_temp=30.0, current_temperature=22.0, temperature=19.0, hvac_action=idle, friendly_name=Schlafzimmer Eve TRV, supported_features=1 @ 2023-10-11T23:05:00.728319+02:00>
2023-10-11 23:05:00.734 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=off, new_hvac_action=idle, old_hvac_action=idle
2023-10-11 23:05:00.738 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Calling update_custom_attributes: {'hvac_mode': 'heat', 'preset_mode': 'eco', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 19.0, 'current_temp': 21.8, 'ext_current_temperature': 15.8999996185303, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'eco', 'saved_target_temp': 16.0, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-11T23:02:50.476466+02:00', 'last_ext_temperature_datetime': '2023-10-11T23:02:50.476466+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.08410617944444447, 'last_update_datetime': '2023-10-11T23:05:00.737087+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': None}
2023-10-11 23:05:00.744 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Checking new cycle. hvac_mode=heat, security_state=False, preset_mode=eco
2023-10-11 23:05:00.744 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - power not configured. check_overpowering not available
2023-10-11 23:05:00.744 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - checking security delta_temp=2.2 delta_ext_temp=2.2 mod_cond=True temp_cond=False climate_cond=False switch_cond=False
2023-10-11 23:05:00.745 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Calling update_custom_attributes: {'hvac_mode': 'heat', 'preset_mode': 'eco', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 19.0, 'current_temp': 21.8, 'ext_current_temperature': 15.8999996185303, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'eco', 'saved_target_temp': 16.0, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-11T23:02:50.476466+02:00', 'last_ext_temperature_datetime': '2023-10-11T23:02:50.476466+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.08410617944444447, 'last_update_datetime': '2023-10-11T23:05:00.745028+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': None}
2023-10-11 23:05:00.760 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_security_state - climate state change
2023-10-11 23:05:00.760 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_window_state - climate state change
2023-10-11 23:05:00.760 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_presence_state - climate state change
2023-10-11 23:05:00.760 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_temp_datetime - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_ext_temp_datetime - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_temperature_slope - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_energy - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_security_state - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_window_state - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_presence_state - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_temp_datetime - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_ext_temp_datetime - climate state change
2023-10-11 23:05:00.761 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_temperature_slope - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_energy - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_security_state - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_window_state - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.binary_sensor] Schlafzimmer Heizung_presence_state - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_temp_datetime - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_last_ext_temp_datetime - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_temperature_slope - climate state change
2023-10-11 23:05:00.762 DEBUG (MainThread) [custom_components.versatile_thermostat.sensor] Schlafzimmer Heizung_energy - climate state change
2023-10-11 23:05:01.135 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - _async_climate_changed new_state is <state climate.schlafzimmer_eve_trv=off; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>], min_temp=7, max_temp=35, current_temperature=22.0, temperature=None, hvac_action=idle, friendly_name=Schlafzimmer Eve TRV, supported_features=1 @ 2023-10-11T23:05:01.129526+02:00>
2023-10-11 23:05:01.136 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Underlying climate changed. Event.new_hvac_mode is off, current_hvac_mode=heat, new_hvac_action=idle, old_hvac_action=idle
2023-10-11 23:05:01.140 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Schlafzimmer Heizung - Calling update_custom_attributes: {'hvac_mode': 'off', 'preset_mode': 'eco', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 19.0, 'current_temp': 21.8, 'ext_current_temperature': 15.8999996185303, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'eco', 'saved_target_temp': 16.0, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-11T23:02:50.476466+02:00', 'last_ext_temperature_datetime': '2023-10-11T23:02:50.476466+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.08410617944444447, 'last_update_datetime': '2023-10-11T23:05:01.138469+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': None}

Homekit Device debug log (one cycle, this continues endlessly too)

2023-10-11 23:05:56.846 DEBUG (MainThread) [aiohomekit.controller.ble.client] Queuing fragment for write: b'\x00\x02j.\x00\x03\x00\x01\x01\x01'
2023-10-11 23:05:56.846 DEBUG (MainThread) [aiohomekit.controller.ble.client] Writing fragment: b'\x82\xca{\x8b\xfc_\x04\x0e9}>\x1f\x92B\xe4\xa2\xf7\x8c[{\x7f\xd9\x17\xd2\xbf\xc3'
2023-10-11 23:05:57.252 DEBUG (MainThread) [aiohomekit.controller.ble.client] Read fragment: b'\x02j\x00'
2023-10-11 23:05:57.252 DEBUG (MainThread) [aiohomekit.pdu] Got PDU 2: TID 6a (Expected: 6a), Status:0, Len:-2 - b'\x02j\x00'
2023-10-11 23:05:57.253 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{(1, 46): {'value': 1}}
2023-10-11 23:05:57.253 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for C3:DC:05:F4:16:2C
2023-10-11 23:05:57.255 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Finished put_characteristics, checking for subscription restore: False
2023-10-11 23:05:57.262 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Populating accessories and characteristics: made_connection=False restore_pending=False
2023-10-11 23:05:57.262 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Writing characteristics: [(1, 46, 0)]; rssi=-84
2023-10-11 23:05:57.262 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Writing characteristics: iid=46 value=0
2023-10-11 23:05:57.263 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1 (Identifier): (1 bytes/<class 'bytes'>) b'\x00'
]

2023-10-11 23:05:57.263 DEBUG (MainThread) [aiohomekit.controller.ble.client] Queuing fragment for write: b'\x00\x02\xe5.\x00\x03\x00\x01\x01\x00'
2023-10-11 23:05:57.264 DEBUG (MainThread) [aiohomekit.controller.ble.client] Writing fragment: b'\xd9\x90\xdc\xf8\x939\x8a>E\xe8\xb6\x90\xeaP8\xa2\xca3Z\xf5\xa4\xdb\x1a\xe0\t,'
2023-10-11 23:05:57.652 DEBUG (MainThread) [aiohomekit.controller.ble.client] Read fragment: b'\x02\xe5\x00'
2023-10-11 23:05:57.652 DEBUG (MainThread) [aiohomekit.pdu] Got PDU 2: TID e5 (Expected: e5), Status:0, Len:-2 - b'\x02\xe5\x00'
2023-10-11 23:05:57.652 DEBUG (MainThread) [aiohomekit.controller.abstract] callback ev:{(1, 46): {'value': 0}}
2023-10-11 23:05:57.653 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for C3:DC:05:F4:16:2C
2023-10-11 23:05:57.654 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Finished put_characteristics, checking for subscription restore: False
2023-10-11 23:05:57.658 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Populating accessories and characteristics: made_connection=False restore_pending=False
2023-10-11 23:05:57.659 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Writing characteristics: [(1, 46, 1)]; rssi=-84
2023-10-11 23:05:57.659 DEBUG (MainThread) [aiohomekit.controller.ble.pairing] Eve Thermo 1E71 [E0:77:D3:8A:FD:2E] (id=C3:DC:05:F4:16:2C): Writing characteristics: iid=46 value=1
2023-10-11 23:05:57.659 DEBUG (MainThread) [aiohomekit.protocol.tlv] sending [
  1 (Identifier): (1 bytes/<class 'bytes'>) b'\x01'
]

TRV configuration

# (…)
"devices": [
      {
        "name": "Eve Thermo 1E71",
        "model": "Eve Thermo 20EBP1701",
        "manfacturer": "Eve Systems",
        "sw_version": "2.1.3",
        "hw_version": "1.1",
        "entities": [
          {
            "original_name": "Eve Thermo 1E71",
            "original_device_class": null,
            "entity_category": null,
            "original_icon": null,
            "icon": null,
            "unit_of_measurement": null,
            "device_class": null,
            "disabled": false,
            "disabled_by": null,
            "state": {
              "entity_id": "climate.schlafzimmer_eve_trv",
              "state": "off",
              "attributes": {
                "hvac_modes": [
                  "off",
                  "heat"
                ],
                "min_temp": 7,
                "max_temp": 35,
                "current_temperature": 19.5,
                "temperature": null,
                "hvac_action": "idle",
                "friendly_name": "Schlafzimmer Eve TRV",
                "supported_features": 1
              },
              "last_changed": "2023-10-11T21:12:42.350486+00:00",
              "last_updated": "2023-10-12T06:00:25.587862+00:00"
            }
          },
# (…)
@Ra72xx
Copy link

Ra72xx commented Oct 12, 2023

Maybe related: With an Aqara E1 thermostat, I can trigger an infinite loop switching back and forth between two target temperatures when manually switching mode on the thermostat hardware several times. I don't really understand what happens here, but it can be stopped when deactivatimg the integration.

@maia
Copy link
Author

maia commented Oct 12, 2023

(Edit: the link I came across which I thought might be related is most likely not related)

@jmcollin78
Copy link
Owner

@maia, this is a vert bad news.
I had a similar bug a few times ago with the security mode on a VTherm over climate. But this is not your case regarding the states:

last_temperature_datetime: '2023-10-12T08:57:12.562924+02:00'
last_ext_temperature_datetime: '2023-10-12T08:51:55.650098+02:00'
security_state: false

and another time when switching off a thermostat and the response was 'on' with hvac_action = 'idle'.

#95
#99

If I look more closely to the logs, what is relevant is that:

Checking new cycle. hvac_mode=off                            <--- the thermostat requested state is off 
...
Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=off, new_hvac_action=idle.  <-- underlying says I'm on (heat) but Idle
... 

 Underlying climate changed. Event.new_hvac_mode is off, current_hvac_mode=heat, new_hvac_action=idle, old_hvac_action=idle.                                                     <-- underlying says finally I'm off.

So the underlying is changing without VTherm command I think.
Are you sure that your EVE thermostat is not controled by HomeKit in parallèl of the control by VTherm.

If yes, this is the issue:
VTHerm says off,
HomeKit says Heat but Idle,
....

and so on.

@jmcollin78 jmcollin78 added the P1 Priority 1 label Oct 13, 2023
@maia
Copy link
Author

maia commented Oct 13, 2023

@jmcollin78 Good thought, but as Eve Thermo devices are Homekit/Thread only (and not Matter), they can only be paired with one smart home system. I'm currently gradually removing these thermostatic valves from my Apple Home setup, resetting them and then repairing them with Home Assistant (as Homekit Device, they have no native integration).

As the issue mentioned above appeared with a thermostatic valve that was added to Home Assistant only 30 minutes earlier, I don't even think there is a way it might have ended up being controlled by another Home Assistant integration.

All I did was adding it as Homekit Device to HA, creating a VTherm device, then adding it to a scheduler-component and then a simple thermostat card. And 30 minutes later I tried turning it off via the UI (as it's too warm outside to heat) and the issue started.

@jmcollin78
Copy link
Owner

I will think about a security to avoid this when its happens. This is quiet dangerous or very annoying when its happens.
I have same kind of configuration (a VTherm exported to Homekit) so I try to reproduce the case.

Waiting for an eventual fix, I suggest you to remove the VTherm and the underlying climate from export to Homekit.
This can be done by adding some lines into the homekit.yaml file:

...
exclude_entities:
    - climate.clim_chambre_localtuya
    - climate.air_conditioner

@jmcollin78
Copy link
Owner

I have made some test with climate in HA and in Homekit, it is working as expected.

@maia
Copy link
Author

maia commented Oct 13, 2023

Neither the thermostatic valve nor the VTherm device are currently exported to Apple Homekit, so excluding them will most likely not help. As mentioned, here is my setup:

  1. Factory reset a Eve Thermo TRV
  2. Add it to Home Assistant
  3. Create a Virtual Thermostat device for this TRV
  4. Add the Virtual Thermostat device to scheduler-component
  5. Add a simple thermostat card for the VTherm device

That's all I did, and as soon as I tried to change the preset/temperature from the lovelace UI, the on/off loop started.

@maia
Copy link
Author

maia commented Oct 13, 2023

And I can easily trigger the issue by clicking a few times on the simple thermostat card, changing the temperature and the presets, turning on/off. I clicked like 5 times and the loop started. Reloading the device in the integration didn't clear the loop, I had to reboot Home Assistant. Here's the simple thermostat config:

type: custom:simple-thermostat
entity: climate.schlafzimmer_heizung
layout:
  step: row
  mode:
    names: true
    icons: false
    headings: false
header:
  name: Schlafzimmer
sensors:
  - entity: binary_sensor.badezimmer_oben_heizung_window_state
    name: Window

@maia
Copy link
Author

maia commented Oct 13, 2023

Update, I think I can now reproduce the issue: The loop starts when changing the target temperature, the preset or the heating/off switch "too fast" in the control of the versatile thermostat device.

It doesn't matter if I make the changes from a simple-thermostat card, from the lovelace UI or from the integration device overview. As soon as I make about 5 changes within 2-3 seconds, the loop starts. The loop can be stopped by disabling the underlying TRV device and reenabling it.

When making the same changes in the underlying TRV device, the problem does not appear. Only when making too many quick changes in the versatile thermostat device, the loop starts.

From my testing, it makes little difference if I change the preset, turn the binary heat/off switch on/off or change the temperature. After clicking a few times (like pressing "+" five times in a row to go from target temp 22,0° to 22.5° and then pressing "-" again for 3 times to go back to 21,0°) the loop begins, e.g.:

  • VTherm is on, preset manual, target temp 20,0°C
  • click + 5 times to change target temp to 22,5°C
  • click - 3 times to change target temp to 21,0°C
  • click + 2 times to change target temp to 22,0°C
  • click - 2 times to change target temp to 21,0°C

I think that whenever the TRV is still changing the valve position to switch to the new target temp, it will get stuck when you already change it to another target temp. But I have no explanation why this is only an issue when controlling it via VTherm. There is no problem when making exactly the same changes from the underlying Eve Thermo TRV device.

@maia
Copy link
Author

maia commented Oct 13, 2023

Here's a 900KB debug log of about 45 seconds time with a stuck loop which I triggered by quickly changing the temperature as described above. It has 137 occurrences of "Checking new cycle", so 2-3 cycles per second: vtherm debug 231013.log.

@jmcollin78
Copy link
Owner

Update, I think I can now reproduce the issue: The loop starts when changing the target temperature, the preset or the heating/off switch "too fast" in the control of the versatile thermostat device....

This will definitively helps me to reproduce to case (+ the logs)

@jmcollin78
Copy link
Owner

Cannot reproduce on my test env and neither on my prod env (my home). My logs are the followings:

2023-10-13 19:04:55.422 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set hvac mode: heat
2023-10-13 19:04:55.425 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set preset_mode: comfort force=True
2023-10-13 19:04:55.434 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Sending event EventType.PRESET_EVENT with data: {'preset': 'comfort'}
2023-10-13 19:04:55.437 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Sending event EventType.HVAC_MODE_EVENT with data: {'hvac_mode': <HVACMode.HEAT: 'heat'>}
2023-10-13 19:04:55.689 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:06:10.242 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 20.5
2023-10-13 19:06:10.579 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:06:10.579 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Target temp have change to 20.0
2023-10-13 19:06:10.580 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 20.0
2023-10-13 19:06:12.787 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.0
2023-10-13 19:06:13.106 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:06:15.054 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 18.5
2023-10-13 19:06:15.402 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:06:15.403 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Target temp have change to 18.0
2023-10-13 19:06:15.403 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 18.0
2023-10-13 19:06:16.643 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 16.5
2023-10-13 19:06:16.945 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:06:16.946 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Target temp have change to 16.0
2023-10-13 19:06:16.946 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 16.0
2023-10-13 19:06:19.969 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 18.5
2023-10-13 19:06:20.294 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:06:20.295 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Target temp have change to 18.0
2023-10-13 19:06:20.295 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 18.0
2023-10-13 19:07:01.788 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 18.5
2023-10-13 19:07:02.370 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.0
2023-10-13 19:07:02.710 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:07:02.919 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.5
2023-10-13 19:07:03.496 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 20.0
2023-10-13 19:07:03.876 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:07:22.418 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.5
2023-10-13 19:07:22.712 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:07:22.713 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Target temp have change to 19.0
2023-10-13 19:07:22.713 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.0
2023-10-13 19:07:23.236 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.0
2023-10-13 19:07:26.742 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 21.5
2023-10-13 19:07:27.051 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None
2023-10-13 19:07:27.051 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Target temp have change to 21.0
2023-10-13 19:07:27.052 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 21.0
2023-10-13 19:07:30.558 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Set target temp: 19.0
2023-10-13 19:07:30.944 INFO (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Thermostat chambre - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=None, old_hvac_action=None

I will compare with your logs. I'm now pretty sure it is a specific behaviour with your TRV thermostat.

@jmcollin78
Copy link
Owner

jmcollin78 commented Oct 13, 2023

Ok having a rapid look i can see that the TRV is answering to command in 6 sec approx. During this time, you have clicked almost 3 times on temperature change:

2023-10-13 18:09:16.549 DEBUG - Checking new cycle. hvac_mode=heat, security_state=False, preset_mode=none
...
2023-10-13 18:09:19.626 INFO - Set target temp: 21.0
2023-10-13 18:09:19.639 DEBUG - Calling update_custom_attributes: {'hvac_mode': 'heat', 'preset_mode': 'none', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 21.0, 'current_temp': 22.8, 'ext_current_temperature': 22.7999992370605, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'none', 'saved_target_temp': 19.5, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'last_ext_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.1314021777777778, 'last_update_datetime': '2023-10-13T18:09:19.638185+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': datetime.datetime(2023, 10, 13, 18, 6, 35, 520071, tzinfo=zoneinfo.ZoneInfo(key='Europe/Vienna'))}
...
2023-10-13 18:09:22.069 INFO - Set target temp: 22.0
2023-10-13 18:09:22.073 DEBUG - Calling update_custom_attributes: {'hvac_mode': 'heat', 'preset_mode': 'none', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 22.0, 'current_temp': 22.8, 'ext_current_temperature': 22.7999992370605, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'none', 'saved_target_temp': 19.5, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'last_ext_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.1314021777777778, 'last_update_datetime': '2023-10-13T18:09:22.072383+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': datetime.datetime(2023, 10, 13, 18, 6, 35, 520071, tzinfo=zoneinfo.ZoneInfo(key='Europe/Vienna'))}
...
2023-10-13 18:09:22.569 DEBUG - _async_climate_changed new_state is <state climate.schlafzimmer_eve_trv=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>], min_temp=10.0, max_temp=30.0, current_temperature=23.0, temperature=22.5, hvac_action=heating, friendly_name=Schlafzimmer Eve TRV, supported_features=1 @ 2023-10-13T18:06:06.444393+02:00>
2023-10-13 18:09:22.576 INFO - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=heating, old_hvac_action=heating

2023-10-13 18:09:22.576 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] Do temperature check. temperature is 22.0, new_state.attributes is {'hvac_modes': [<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>], 'min_temp': 10.0, 'max_temp': 30.0, 'current_temperature': 23.0, 'temperature': 22.5, 'hvac_action': <HVACAction.HEATING: 'heating'>, 'friendly_name': 'Schlafzimmer Eve TRV', 'supported_features': <ClimateEntityFeature.TARGET_TEMPERATURE: 1>}
2023-10-13 18:09:22.576 INFO - Target temp have change to 22.5
2023-10-13 18:09:22.576 INFO - Set target temp: 22.5
2023-10-13 18:09:22.586 DEBUG - Calling update_custom_attributes: {'hvac_mode': 'heat', 'preset_mode': 'none', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 22.5, 'current_temp': 22.8, 'ext_current_temperature': 22.7999992370605, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'none', 'saved_target_temp': 19.5, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'last_ext_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.1314021777777778, 'last_update_datetime': '2023-10-13T18:09:22.585114+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': datetime.datetime(2023, 10, 13, 18, 6, 35, 520071, tzinfo=zoneinfo.ZoneInfo(key='Europe/Vienna'))}
...
2023-10-13 18:09:25.323 DEBUG - _async_climate_changed new_state is <state climate.schlafzimmer_eve_trv=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>], min_temp=10.0, max_temp=30.0, current_temperature=23.0, temperature=21.0, hvac_action=heating, friendly_name=Schlafzimmer Eve TRV, supported_features=1 @ 2023-10-13T18:06:06.444393+02:00>
2023-10-13 18:09:25.323 INFO - Underlying climate changed. Event.new_hvac_mode is heat, current_hvac_mode=heat, new_hvac_action=heating, old_hvac_action=heating
2023-10-13 18:09:25.324 DEBUG (MainThread) [custom_components.versatile_thermostat.climate] Do temperature check. temperature is 22.5, new_state.attributes is {'hvac_modes': [<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>], 'min_temp': 10.0, 'max_temp': 30.0, 'current_temperature': 23.0, 'temperature': 21.0, 'hvac_action': <HVACAction.HEATING: 'heating'>, 'friendly_name': 'Schlafzimmer Eve TRV', 'supported_features': <ClimateEntityFeature.TARGET_TEMPERATURE: 1>}
2023-10-13 18:09:25.324 INFO - Target temp have change to 21.0
2023-10-13 18:09:25.324 INFO - Set target temp: 21.0
2023-10-13 18:09:25.333 DEBUG - Calling update_custom_attributes: {'hvac_mode': 'heat', 'preset_mode': 'none', 'type': 'thermostat_over_climate', 'eco_temp': 19.0, 'boost_temp': 21.0, 'comfort_temp': 20.0, 'eco_away_temp': 17.0, 'boost_away_temp': 19.0, 'comfort_away_temp': 18.0, 'power_temp': None, 'target_temp': 21.0, 'current_temp': 22.8, 'ext_current_temperature': 22.7999992370605, 'current_power': None, 'current_power_max': None, 'saved_preset_mode': 'none', 'saved_target_temp': 19.5, 'saved_hvac_mode': None, 'window_state': None, 'motion_state': None, 'overpowering_state': None, 'presence_state': 'on', 'window_auto_state': False, 'security_delay_min': 60, 'security_min_on_percent': 0.5, 'security_default_on_percent': 0.1, 'last_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'last_ext_temperature_datetime': '2023-10-13T18:03:32.146893+02:00', 'security_state': False, 'minimal_activation_delay_sec': 10, 'device_power': 1.0, 'mean_cycle_power': None, 'total_energy': 0.1314021777777778, 'last_update_datetime': '2023-10-13T18:09:25.328725+02:00', 'timezone': 'Europe/Vienna', 'window_delay_sec': 30, 'window_auto_open_threshold': 0.05, 'window_auto_close_threshold': 0.0, 'window_auto_max_duration': 60, 'underlying_climate_1': None, 'underlying_climate_2': None, 'underlying_climate_3': None, 'start_hvac_action_date': datetime.datetime(2023, 10, 13, 18, 6, 35, 520071, tzinfo=zoneinfo.ZoneInfo(key='Europe/Vienna'))}

You send the 21.0 target temp at 18:09:19:
2023-10-13 18:09:19.626 INFO - Set target temp: 21.0
and the TRV change its target temp at 18:09:25:

2023-10-13 18:09:25.323 INFO - Underlying climate changed.
2023-10-13 18:09:25.324 INFO - Target temp have change to 21.0

And this is not "normal". If you look at my logs, the "underlying climate changed" log is in the same second.

So I guess this is the reason why it is not reproductible (and until now you are the only one with this problem).
I continue analysis tomorrow because I have to leave now.

EDIT : this is not a reason to loop indeed

@maia
Copy link
Author

maia commented Oct 13, 2023

Hmm, well clicking 6x in 3 seconds happens when you see the thermo is set to 21°C, you decide you want it warmer, so you click 3x the "+" to 22,5°C, then decide that it's a waste of energy and you'll revert back to 21°C, so you click 3x the "-". Boom, 6 clicks in 3 seconds.

(And as mentioned, when doing this directly on the hardware itself or on the HA underlying thermostat device, it's not an issue. Only when doing this in the VTherm device it is an issue.

Thanks for looking into it!

@Ra72xx
Copy link

Ra72xx commented Oct 14, 2023

In my case I can reproduce the behavior (if it's the same) when clicking my Aqara Thermostat directly on the hardware 3x in a row, which is the sequence used to start a valve calibration. Seemingly this three fast clicks are interpreted somehow by VT and cause confustion.

@jmcollin78
Copy link
Owner

Ok, I got exactly the case (for @maia at least). This is a side effect of the #101 issue and the #113 issue that were released in the last version when the response of the underlying is slow.

The scenario is the following:

  1. the user change target temperature, let says 20°,
  2. the VTherm inform all underlying that the new target is 20° (Multiple thermostats when using "thermostat over another thermostat" mode #113),
  3. the user change target temperature one again, let says 21°,
  4. the VTherm inform all underlying that the new target is 21° (Multiple thermostats when using "thermostat over another thermostat" mode #113),
  5. the underlying response to first change saying that internal target temp is now 20°,
  6. then VTherm inform all underlying that the new target is 20° (Versatile Thermostat does not follow target temperature from underlying thermostat #101),
  7. the underlying response to 2nd change saying that internal target temp is now 21°,
  8. then VTherm inform all underlying that the new target is 21° (Versatile Thermostat does not follow target temperature from underlying thermostat #101),
  9. response to the 6 (set to 20°),
  10. ....

If response of the underlying is instantaneous, you don't have this effect because the target temp of the underlying is equal to the target temp of the VTherm and nothing is done by VTherm.

Fixing this is tricky (without removing #110). I will to see with your logs if i can ignore the target of underlying when a manuel change have been made after. I'm sure I will have all the dates to do that.

jmcollin78 pushed a commit that referenced this issue Oct 14, 2023
@jmcollin78
Copy link
Owner

jmcollin78 commented Oct 14, 2023

Hello @maia and @Ra72xx ,

I have published a pre-release with more logs to see if I can use the event dates to filter "late" events coming for your underlying climate. Can you please, install it, redo the procedure to reproduce the bug and send me the log you have.

Don't worry, I have commented the #101 which causes the loop.

Thank you !

EDIT: It is there: https://github.com/jmcollin78/versatile_thermostat/releases/tag/3.5.3.beta4

@maia
Copy link
Author

maia commented Oct 14, 2023

Using 3.5.3beta4 I managed to recreate the bug, it got stuck in a loop again. Maybe it took a bit longer, but here is the log, I hope it's useful:

2023-10-14 13:21:27.621 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:27.621030+02:00
2023-10-14 13:21:31.081 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:31.081227+02:00
2023-10-14 13:21:31.782 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:31.081227+02:00 old_state_date_changed=2023-10-14 11:19:15.317025+00:00 old_state_date_updated=2023-10-14 11:19:15.317025+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:31.756795+00:00
2023-10-14 13:21:31.782 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - Target temp have change to 20.0
2023-10-14 13:21:32.603 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:31.081227+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:31.756795+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:32.599937+00:00
2023-10-14 13:21:32.626 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:31.081227+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:32.599937+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:32.624104+00:00
2023-10-14 13:21:34.455 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:34.455408+02:00
2023-10-14 13:21:34.810 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:34.455408+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:32.624104+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:34.804123+00:00
2023-10-14 13:21:36.972 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:36.972181+02:00
2023-10-14 13:21:37.303 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:36.972181+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:34.804123+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:37.297865+00:00
2023-10-14 13:21:40.200 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:40.200319+02:00
2023-10-14 13:21:40.806 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:40.200319+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:37.297865+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:40.803360+00:00
2023-10-14 13:21:41.949 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:41.949462+02:00
2023-10-14 13:21:42.303 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:41.949462+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:40.803360+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:42.300468+00:00
2023-10-14 13:21:43.909 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:43.909904+02:00
2023-10-14 13:21:44.310 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:43.909904+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:42.300468+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:44.305281+00:00
2023-10-14 13:21:45.866 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:45.866560+02:00
2023-10-14 13:21:46.298 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:45.866560+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:44.305281+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:46.296425+00:00
2023-10-14 13:21:49.225 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:49.225159+02:00
2023-10-14 13:21:49.815 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:49.225159+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:46.296425+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:49.811699+00:00
2023-10-14 13:21:52.498 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:52.498150+02:00
2023-10-14 13:21:52.796 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:52.498150+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:49.811699+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:52.794632+00:00
2023-10-14 13:21:56.144 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:56.144182+02:00
2023-10-14 13:21:56.845 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:56.144182+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:52.794632+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:56.819658+00:00
2023-10-14 13:21:56.845 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - Target temp have change to 23.0
2023-10-14 13:21:56.865 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:56.144182+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:56.819658+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:56.861679+00:00
2023-10-14 13:21:57.760 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:57.760826+02:00
2023-10-14 13:21:58.798 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:21:58.798310+02:00
2023-10-14 13:21:59.306 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:21:58.798310+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:56.861679+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:21:59.300923+00:00
2023-10-14 13:22:00.427 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:22:00.427173+02:00
2023-10-14 13:22:00.834 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:00.427173+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:21:59.300923+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:22:00.827916+00:00
2023-10-14 13:22:00.907 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:00.427173+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:22:00.827916+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:22:00.904588+00:00
2023-10-14 13:22:07.422 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:22:07.422841+02:00
2023-10-14 13:22:10.488 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time is now 2023-10-14 13:22:10.488324+02:00
2023-10-14 13:22:10.930 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:22:00.904588+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:22:10.925280+00:00
2023-10-14 13:22:10.956 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:22:10.925280+00:00 new_state_date_changed=2023-10-14 11:21:31.756795+00:00 new_state_date_updated=2023-10-14 11:22:10.953939+00:00
2023-10-14 13:22:14.302 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:21:31.756795+00:00 old_state_date_updated=2023-10-14 11:22:10.953939+00:00 new_state_date_changed=2023-10-14 11:22:14.291897+00:00 new_state_date_updated=2023-10-14 11:22:14.291897+00:00
2023-10-14 13:22:14.806 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:14.291897+00:00 old_state_date_updated=2023-10-14 11:22:14.291897+00:00 new_state_date_changed=2023-10-14 11:22:14.802457+00:00 new_state_date_updated=2023-10-14 11:22:14.802457+00:00
2023-10-14 13:22:15.286 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:14.802457+00:00 old_state_date_updated=2023-10-14 11:22:14.802457+00:00 new_state_date_changed=2023-10-14 11:22:15.282698+00:00 new_state_date_updated=2023-10-14 11:22:15.282698+00:00
2023-10-14 13:22:15.875 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:15.282698+00:00 old_state_date_updated=2023-10-14 11:22:15.282698+00:00 new_state_date_changed=2023-10-14 11:22:15.868172+00:00 new_state_date_updated=2023-10-14 11:22:15.868172+00:00
2023-10-14 13:22:16.387 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:15.868172+00:00 old_state_date_updated=2023-10-14 11:22:15.868172+00:00 new_state_date_changed=2023-10-14 11:22:16.383901+00:00 new_state_date_updated=2023-10-14 11:22:16.383901+00:00
2023-10-14 13:22:17.130 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:16.383901+00:00 old_state_date_updated=2023-10-14 11:22:16.383901+00:00 new_state_date_changed=2023-10-14 11:22:17.126384+00:00 new_state_date_updated=2023-10-14 11:22:17.126384+00:00
2023-10-14 13:22:17.648 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:17.126384+00:00 old_state_date_updated=2023-10-14 11:22:17.126384+00:00 new_state_date_changed=2023-10-14 11:22:17.126384+00:00 new_state_date_updated=2023-10-14 11:22:17.645471+00:00
2023-10-14 13:22:17.693 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:17.126384+00:00 old_state_date_updated=2023-10-14 11:22:17.645471+00:00 new_state_date_changed=2023-10-14 11:22:17.689498+00:00 new_state_date_updated=2023-10-14 11:22:17.689498+00:00
2023-10-14 13:22:18.227 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:17.689498+00:00 old_state_date_updated=2023-10-14 11:22:17.689498+00:00 new_state_date_changed=2023-10-14 11:22:18.221907+00:00 new_state_date_updated=2023-10-14 11:22:18.221907+00:00
2023-10-14 13:22:18.966 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:18.221907+00:00 old_state_date_updated=2023-10-14 11:22:18.221907+00:00 new_state_date_changed=2023-10-14 11:22:18.959928+00:00 new_state_date_updated=2023-10-14 11:22:18.959928+00:00
2023-10-14 13:22:19.478 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:18.959928+00:00 old_state_date_updated=2023-10-14 11:22:18.959928+00:00 new_state_date_changed=2023-10-14 11:22:19.475104+00:00 new_state_date_updated=2023-10-14 11:22:19.475104+00:00
2023-10-14 13:22:19.970 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:19.475104+00:00 old_state_date_updated=2023-10-14 11:22:19.475104+00:00 new_state_date_changed=2023-10-14 11:22:19.968188+00:00 new_state_date_updated=2023-10-14 11:22:19.968188+00:00
2023-10-14 13:22:20.490 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:19.968188+00:00 old_state_date_updated=2023-10-14 11:22:19.968188+00:00 new_state_date_changed=2023-10-14 11:22:20.486541+00:00 new_state_date_updated=2023-10-14 11:22:20.486541+00:00
2023-10-14 13:22:20.970 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:20.486541+00:00 old_state_date_updated=2023-10-14 11:22:20.486541+00:00 new_state_date_changed=2023-10-14 11:22:20.966463+00:00 new_state_date_updated=2023-10-14 11:22:20.966463+00:00
2023-10-14 13:22:21.561 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:20.966463+00:00 old_state_date_updated=2023-10-14 11:22:20.966463+00:00 new_state_date_changed=2023-10-14 11:22:21.557339+00:00 new_state_date_updated=2023-10-14 11:22:21.557339+00:00
2023-10-14 13:22:22.067 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:21.557339+00:00 old_state_date_updated=2023-10-14 11:22:21.557339+00:00 new_state_date_changed=2023-10-14 11:22:22.063358+00:00 new_state_date_updated=2023-10-14 11:22:22.063358+00:00
2023-10-14 13:22:22.818 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:22.063358+00:00 old_state_date_updated=2023-10-14 11:22:22.063358+00:00 new_state_date_changed=2023-10-14 11:22:22.814000+00:00 new_state_date_updated=2023-10-14 11:22:22.814000+00:00
2023-10-14 13:22:23.305 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:22.814000+00:00 old_state_date_updated=2023-10-14 11:22:22.814000+00:00 new_state_date_changed=2023-10-14 11:22:23.300466+00:00 new_state_date_updated=2023-10-14 11:22:23.300466+00:00
2023-10-14 13:22:23.812 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:23.300466+00:00 old_state_date_updated=2023-10-14 11:22:23.300466+00:00 new_state_date_changed=2023-10-14 11:22:23.808889+00:00 new_state_date_updated=2023-10-14 11:22:23.808889+00:00
2023-10-14 13:22:24.329 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:23.808889+00:00 old_state_date_updated=2023-10-14 11:22:23.808889+00:00 new_state_date_changed=2023-10-14 11:22:23.808889+00:00 new_state_date_updated=2023-10-14 11:22:24.327292+00:00
2023-10-14 13:22:24.373 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:23.808889+00:00 old_state_date_updated=2023-10-14 11:22:24.327292+00:00 new_state_date_changed=2023-10-14 11:22:24.370399+00:00 new_state_date_updated=2023-10-14 11:22:24.370399+00:00
2023-10-14 13:22:24.918 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:24.370399+00:00 old_state_date_updated=2023-10-14 11:22:24.370399+00:00 new_state_date_changed=2023-10-14 11:22:24.912119+00:00 new_state_date_updated=2023-10-14 11:22:24.912119+00:00
2023-10-14 13:22:25.664 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:24.912119+00:00 old_state_date_updated=2023-10-14 11:22:24.912119+00:00 new_state_date_changed=2023-10-14 11:22:25.659580+00:00 new_state_date_updated=2023-10-14 11:22:25.659580+00:00
2023-10-14 13:22:26.170 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:25.659580+00:00 old_state_date_updated=2023-10-14 11:22:25.659580+00:00 new_state_date_changed=2023-10-14 11:22:26.166175+00:00 new_state_date_updated=2023-10-14 11:22:26.166175+00:00
2023-10-14 13:22:26.653 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:26.166175+00:00 old_state_date_updated=2023-10-14 11:22:26.166175+00:00 new_state_date_changed=2023-10-14 11:22:26.648386+00:00 new_state_date_updated=2023-10-14 11:22:26.648386+00:00
2023-10-14 13:22:27.158 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:26.648386+00:00 old_state_date_updated=2023-10-14 11:22:26.648386+00:00 new_state_date_changed=2023-10-14 11:22:27.154588+00:00 new_state_date_updated=2023-10-14 11:22:27.154588+00:00
2023-10-14 13:22:27.660 WARNING (MainThread) [custom_components.versatile_thermostat.climate] VersatileThermostat-Vorzimmer Heizung - last_change_time=2023-10-14 13:22:10.488324+02:00 old_state_date_changed=2023-10-14 11:22:27.154588+00:00 old_state_date_updated=2023-10-14 11:22:27.154588+00:00 new_state_date_changed=2023-10-14 11:22:27.655267+00:00 new_state_date_updated=2023-10-14 11:22:27.655267+00:00

@jmcollin78
Copy link
Owner

I need also non WARNING logs.

@maia
Copy link
Author

maia commented Oct 14, 2023

I need also non WARNING logs.

You mean I should enable debug logging? Because the above part is the only thing showing up in my HA logs. Maybe there's a way to change the log level to info, but I'd need to check how, I'm running the default.

@maia
Copy link
Author

maia commented Oct 14, 2023

Here's a log with debug set for the integration and info for everything else. It's a minute long. Until about 15:55:22 I manually clicked and changed the target temp and switched heat/off a few times, then the loop started. Near the end of the log I disabled the underlying TRV: VTherm loop 231014.log

@jmcollin78
Copy link
Owner

I see in another thread that you don't have the INFO log level ?
You should something like that in your config/logger.yaml file:

...
default: warning
logs:
  custom_components.versatile_thermostat: info

But above you gave me logs with debug level (hte 900 kb logs). So I guess you known how to change the log level.

jmcollin78 pushed a commit that referenced this issue Oct 14, 2023
@jmcollin78
Copy link
Owner

@maia I have a good new for you. With your last log, I think I found a way to avoid loops.
You can try this https://github.com/jmcollin78/versatile_thermostat/releases/tag/3.5.3.beta6 and let me know.

@Ra72xx I suggest you to install also the 3.5.3.beta6 and do the procedure (click 3 times).

I have tested on my home and it is working fine (but I don't reproduce the loop).

If it works you should see some log like this:
underlying event is received less than 10 sec after command. Forget it to avoid loop

@Ra72xx
Copy link

Ra72xx commented Oct 15, 2023

Just q auick first "thumbs up": I had no time to enable and look into the logs, but "my error" seems not to occur anymore with the beta version.

@jmcollin78
Copy link
Owner

Just q auick first "thumbs up": I had no time to enable and look into the logs, but "my error" seems not to occur anymore with the beta version.

I will wait for @maia feedback and then I will release the fix.

jmcollin78 added a commit that referenced this issue Oct 15, 2023
* Issue #121 - loop when underlying is slow
* Issue #121 - try fix
* Release 3.5.3
* Fix tests step
@jmcollin78 jmcollin78 added the developed When development is done and tested label Oct 15, 2023
@maia
Copy link
Author

maia commented Oct 15, 2023

Great news: I cannot reproduce the issue anymore. Jean-Marc, thanks a lot for all your work. (I've actually bought you some beers a few days ago, I'm seeing a transaction on my Apple Pay, but you didn't receive it. The support team is looking into what happened and will hopefully fix it on Monday)

@jmcollin78
Copy link
Owner

I just push the release ! 3.5.3 which officialize the fix.&

Thnak for the beer, I really appreciate. Cheers from France !

@Ra72xx
Copy link

Ra72xx commented Oct 15, 2023

When playing around with the hardware thermostat, I noticed that some adjustments done manually with the knob (to be honest, some quickly done up/done regulations) were not implemented (seemingly reverted) after a few seconds. I assume that is a side effect of the fix?
This is not really a problem in real-world scenarios, however. Thanks for the fix!

@jmcollin78
Copy link
Owner

When playing around with the hardware thermostat, I noticed that some adjustments done manually with the knob (to be honest, some quickly done up/done regulations) were not implemented (seemingly reverted) after a few seconds. I assume that is a side effect of the fix? This is not really a problem in real-world scenarios, however. Thanks for the fix!

Yes. Exactly, I discarded some events when it comes just after a manual change (and so avoid the loop). The delay is 10 sec.
Mixing control with VTherm and directly on the device will cause this effect.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
developed When development is done and tested P1 Priority 1
Projects
None yet
Development

No branches or pull requests

3 participants