nielsfaber / scheduler-component

Custom component for HA that enables the creation of scheduler entities
GNU General Public License v3.0
622 stars 40 forks source link

Climate Target Temp Reverts a few seconds after being changed by Scheduler #311

Closed gloseem closed 5 months ago

gloseem commented 9 months ago

Hi All,

I am having trouble finding the root cause to an issue using a thermostat with this Scheduler.

I am using this integration and companion Scheduler Card to set the target temperature of my thermostat. Most of the time this works without issue.

However, on some occasions, the target temperature will reset to the previous value a few seconds after being set by the Scheduler.

Here is what I’m seeing in the logbook: Screenshot 2023-11-22 153232

  1. At 6AM, the scheduler is triggered
  2. At 06:00:02 the scheduler sets the climate target temp to 20
  3. At 06:00:07 something sets the climate target temp to 16 (the previous value).

I’m having trouble determining what is actually is setting the temperature back to 16. I have tried two different physical thermostats, but the issue happens with both. I have also heard that another user is seeing the same issue with a Nest thermostat. It is intermittent and used to occur once or twice a month, after the past several months and a number of updates to HomeAssistant, it is now happening several times a week. There isn’t any errors or warnings shown in the log that seem to help.

log entries:

2023-03-02 21:30:00.003 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=climate, service=set_temperature, service_data=hvac_mode=heat, temperature=16, entity_id=['climate.great_room_thermostat']>
2023-03-02 21:30:00.005 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.schedule_2851cf, old_state=<state switch.schedule_2851cf=on; weekdays=['daily'], timeslots=['21:30:00'], entities=['climate.great_room_thermostat'], actions=[{'service': 'climate.set_temperature', 'data': {'hvac_mode': 'heat', 'temperature': 16}}], current_slot=None, next_slot=0, next_trigger=2023-03-02T21:30:00-05:00, tags=[], icon=mdi:calendar-clock, friendly_name=Schedule #2851cf @ 2023-03-01T21:31:00.010500-05:00>, new_state=<state switch.schedule_2851cf=triggered; weekdays=['daily'], timeslots=['21:30:00'], entities=['climate.great_room_thermostat'], actions=[{'service': 'climate.set_temperature', 'data': {'hvac_mode': 'heat', 'temperature': 16}}], current_slot=0, next_slot=0, next_trigger=2023-03-02T21:30:00-05:00, tags=[], icon=mdi:calendar-clock, friendly_name=Schedule #2851cf @ 2023-03-02T21:30:00.005555-05:00>>
2023-03-02 21:30:00.012 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event scheduler_updated[L]>
2023-03-02 21:30:02.304 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=climate.great_room_thermostat, old_state=<state climate.great_room_thermostat=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>, <HVACMode.COOL: 'cool'>, <HVACMode.HEAT_COOL: 'heat_cool'>], min_temp=5, max_temp=35, fan_modes=['Auto low', 'Low'], preset_modes=['none', 'Auxiliary'], current_temperature=19.5, temperature=20, target_temp_high=None, target_temp_low=None, current_humidity=40, fan_mode=Auto low, hvac_action=idle, preset_mode=none, fan_state=Idle / off, friendly_name=Great Room Thermostat, supported_features=ClimateEntityFeature.PRESET_MODE|FAN_MODE|TARGET_TEMPERATURE_RANGE|TARGET_TEMPERATURE @ 2023-02-25T17:57:19.434535-05:00>, new_state=<state climate.great_room_thermostat=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>, <HVACMode.COOL: 'cool'>, <HVACMode.HEAT_COOL: 'heat_cool'>], min_temp=5, max_temp=35, fan_modes=['Auto low', 'Low'], preset_modes=['none', 'Auxiliary'], current_temperature=19.5, temperature=16, target_temp_high=None, target_temp_low=None, current_humidity=40, fan_mode=Auto low, hvac_action=idle, preset_mode=none, fan_state=Idle / off, friendly_name=Great Room Thermostat, supported_features=ClimateEntityFeature.PRESET_MODE|FAN_MODE|TARGET_TEMPERATURE_RANGE|TARGET_TEMPERATURE @ 2023-02-25T17:57:19.434535-05:00>>
2023-03-02 21:30:02.313 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.hvac_target_temp, old_state=<state sensor.hvac_target_temp=20; friendly_name=HVAC Target Temp @ 2023-03-02T06:00:02.327935-05:00>, new_state=<state sensor.hvac_target_temp=16; friendly_name=HVAC Target Temp @ 2023-03-02T21:30:02.313194-05:00>>
2023-03-02 21:30:07.399 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=climate.great_room_thermostat, old_state=<state climate.great_room_thermostat=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>, <HVACMode.COOL: 'cool'>, <HVACMode.HEAT_COOL: 'heat_cool'>], min_temp=5, max_temp=35, fan_modes=['Auto low', 'Low'], preset_modes=['none', 'Auxiliary'], current_temperature=19.5, temperature=16, target_temp_high=None, target_temp_low=None, current_humidity=40, fan_mode=Auto low, hvac_action=idle, preset_mode=none, fan_state=Idle / off, friendly_name=Great Room Thermostat, supported_features=ClimateEntityFeature.PRESET_MODE|FAN_MODE|TARGET_TEMPERATURE_RANGE|TARGET_TEMPERATURE @ 2023-02-25T17:57:19.434535-05:00>, new_state=<state climate.great_room_thermostat=heat; hvac_modes=[<HVACMode.OFF: 'off'>, <HVACMode.HEAT: 'heat'>, <HVACMode.COOL: 'cool'>, <HVACMode.HEAT_COOL: 'heat_cool'>], min_temp=5, max_temp=35, fan_modes=['Auto low', 'Low'], preset_modes=['none', 'Auxiliary'], current_temperature=19.5, temperature=20, target_temp_high=None, target_temp_low=None, current_humidity=40, fan_mode=Auto low, hvac_action=idle, preset_mode=none, fan_state=Idle / off, friendly_name=Great Room Thermostat, supported_features=ClimateEntityFeature.PRESET_MODE|FAN_MODE|TARGET_TEMPERATURE_RANGE|TARGET_TEMPERATURE @ 2023-02-25T17:57:19.434535-05:00>>
2023-03-02 21:30:07.407 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.hvac_target_temp, old_state=<state sensor.hvac_target_temp=16; friendly_name=HVAC Target Temp @ 2023-03-02T21:30:02.313194-05:00>, new_state=<state sensor.hvac_target_temp=20; friendly_name=HVAC Target Temp @ 2023-03-02T21:30:07.407266-05:00>>

I’ve scoured what documentation I could find to no avail and my searching on the issue doesnt seem to hit the right keywords. Any advice on where to start investigating the issue would be hugely appreciated!!

e

Screenshot 2023-02-02 120211

jespergjedde commented 8 months ago

I see the same issue. I tried to find a log for the scheduler actions but was not able to find it. "Scheduler changed ...." or similar, Maybe I look the wrong places.

sven337 commented 8 months ago

I see the same issue. It's not every time, far from it. When it happens, the temperature will revert right away to the previous value.

I wonder whether this is related to the scheduler component, or HA itself. I have been able to observe the "revert" behavior directly in HA itself (albeit on thermostatic valves that had schedules on them, so the scheduler component might have had an influence).

Happy to help debug this, but I'd need help to know what to provide and how.

Panoramiac commented 8 months ago

I have the same issue here with my TRVs. At 5:00 it is set shortly to 21.5 and then back to 19°: image

nielsfaber commented 7 months ago

I believe this issue could be caused by a compatibility issue between this integration and your thermostat. Scheduler implements a rather unusual way of controlling the thermostat: https://github.com/nielsfaber/scheduler-component/blob/75a60ae7e76d7d550b1fcd038c01e9d20bd0fad7/custom_components/scheduler/actions.py#L66-L101

In plain english, it performs the following (lets assume climate.thermostat is the entity and temperature is set to 20):

  1. Call service 'climate.set_temperature' for climate.thermostat with service data 'hvac_mode: heat, temperature: 20'
  2. Wait for 5 seconds
  3. Call service 'climate.set_hvac_mode' for climate.thermostat with service data 'hvac_mode: heat'
  4. Wait for 5 seconds
  5. Call service 'climate.set_temperature' for climate.thermostat with service data 'temperature: 20'

Step 3+4 will only be executed if the thermostat is not yet in mode 'heat'. Step 5 will only be executed if the thermostat does not have setpoint 20.

HA supports setting both the operation mode (heat) and setpoint (20) via the service 'climate.set_temperature' (step 1). However, not all thermostat integrations support this, some ignore the operation mode. In this case the device could remain off. For this case, step 3 is added. In some integrations, the thermostat changes to a predefined setpoint when changing the mode. Step 5 is added to ensure the right setpoint is used.

@gloseem Looking at your case, I believe your thermostat sets itself to 16 degrees when the mode is changed from off to heat. You could verify this by calling service 'climate.set_hvac_mode' via the developer tools panel. On top of that, the step 5 seems to be skipped. Perhaps it takes more than 5 seconds for your climate device to process the previous command and update the state of the entity.

@all Please enable debug logging for the scheduler integration by adding this to the configuration.yaml (and restart HA afterwards):

logger:
  default: warning
  logs:
    custom_components.scheduler: debug

At the time the schedule is triggered, you should see something like this:

2024-01-07 09:19:44.642 DEBUG (MainThread) [custom_components.scheduler.switch] Schedule 0d1755 is starting in a timeslot, proceed with actions 2024-01-07 09:19:44.642 DEBUG (MainThread) [custom_components.scheduler.actions] [0d1755]: Executing service climate.set_temperature on entity climate.my_climate 2024-01-07 09:19:44.653 DEBUG (MainThread) [custom_components.scheduler.actions] [0d1755]: Postponing next action for 5 seconds 2024-01-07 09:19:49.653 DEBUG (MainThread) [custom_components.scheduler.actions] [0d1755]: Executing service climate.set_hvac_mode on entity climate.my_climate 2024-01-07 09:19:49.654 DEBUG (MainThread) [custom_components.scheduler.actions] [0d1755]: Action has no effect, skipping 2024-01-07 09:19:49.654 DEBUG (MainThread) [custom_components.scheduler.actions] [0d1755]: Executing service climate.set_temperature on entity climate.my_climate 2024-01-07 09:19:49.656 DEBUG (MainThread) [custom_components.scheduler.actions] [0d1755]: Finished execution of actions

Please post the loggings for the occurence where you experience the issue.

On top of that, I created a script which mimics the behaviour of scheduler for controlling your thermostat. Please add this script to the scripts.yaml and execute it to see if your thermostat properly responds to it. The scripts also adds loggings for the performed steps.

thermostat_test:
  variables:
    entity: climate.my_thermostat # change to your entity
    temperature: 20 # change if desired
    mode: heat
    delay: 5
  sequence:
    - service: system_log.write
      data:
        message: "-- Start of script --"
    - choose:
        - conditions:
            - "{{ state_attr(entity, 'temperature') == temperature }}"
          sequence:
            - service: system_log.write
              data:
                message: "Temperature is already {{ temperature }}, skipping step"
      default:
        - service: system_log.write
          data:
            message: "Setting temperature to {{ temperature }} and mode to {{ mode }}"
        - service: climate.set_temperature
          data_template:
            entity_id: "{{ entity }}"
            temperature: "{{ temperature }}"
            hvac_mode: "{{ mode }}"
        - service: system_log.write
          data:
            message: "Waiting for {{ delay }} seconds"
        - delay: "{{ delay }}"
    - choose:
        - conditions:
            - "{{ is_state(entity, mode) }}"
          sequence:
            - service: system_log.write
              data:
                message: "Mode is already {{ mode }}, skipping step"
      default:
        - service: system_log.write
          data:
            message: "Setting mode to {{ mode }}"
        - service: climate.set_hvac_mode
          data_template:
            entity_id: "{{ entity }}"
            hvac_mode: "{{ mode }}"
        - service: system_log.write
          data:
            message: "Waiting for {{ delay }} seconds"
        - delay: "{{ delay }}"
    - choose:
        - conditions:
            - "{{ state_attr(entity, 'temperature') == temperature }}"
          sequence:
            - service: system_log.write
              data:
                message: "Temperature is already {{ temperature }}, skipping step"
      default:
        - service: system_log.write
          data:
            message: "Setting temperature to {{ temperature }}"
        - service: climate.set_temperature
          data_template:
            entity_id: "{{ entity }}"
            temperature: "{{ temperature }}"
    - service: system_log.write
      data:
        message: "-- End of script --"

Please share your findings.

wranglatang commented 7 months ago

I have a similar issue with my Shelly TRV’s I don’t believe it’s related to the TRV being set to “heat” as I have mine always set to “heat” and I am only adjusting the temperature with the scheduler component.

jespergjedde commented 7 months ago

I see the same issue. I tried to find a log for the scheduler actions but was not able to find it. "Scheduler changed ...." or similar, Maybe I look the wrong places.

This problem is gone for me. I cannot explain why - but i dont see this behavior anymore, Sorry for not returning sooner.

wranglatang commented 7 months ago

I still see this issue on a daily basis.

nielsfaber commented 7 months ago

@wranglatang if you want to see this fixed, please post your results of the tests I requested.

wranglatang commented 7 months ago

I can absolutely do that, but I’m away on business now will do it when I’m home. However I think you are right!! It’s related to the setting of the HVAC mode. My Shelly TRV defaults to 20 when the hvac mode is updated! Would be great if it’s possible to toggle if that feature / setting is used when configuring the schedule for climates

wranglatang commented 7 months ago

Morning! I have executed the testing using the script and that doesn't seem to show the problem (however i dont always see the problem when using the scheduler component).

2024-01-19 08:28:52.218 ERROR (MainThread) [homeassistant.components.system_log.external] -- Start of script --
2024-01-19 08:28:52.219 ERROR (MainThread) [homeassistant.components.system_log.external] Setting temperature to 18 and mode to heat
2024-01-19 08:28:52.221 ERROR (MainThread) [homeassistant.components.system_log.external] Waiting for 5 seconds
2024-01-19 08:28:58.234 ERROR (MainThread) [homeassistant.components.system_log.external] Mode is already heat, skipping step
2024-01-19 08:28:58.236 ERROR (MainThread) [homeassistant.components.system_log.external] Temperature is already 18, skipping step
2024-01-19 08:28:58.236 ERROR (MainThread) [homeassistant.components.system_log.external] -- End of script --

One thing i have done recently which has seemed to help is i manually adjusted the delay time in the scheduler component from 5 to 10 - this seems to give the TRV time to process the initial "on" (default to 20) then receive and process the temp setting (typically 18) instead of getting stuck at 20

image

nielsfaber commented 7 months ago

@wranglatang thanks for participating in testing! Your tests prove that it’s your climate device setting itself to 20C, but apparently this is not visible within 5 seconds. I will look for a generic way to fix this issue, for example by watching for an entire minute after applying the setting, and checking if the device jumps to another setting.

gloseem commented 7 months ago

Hi @nielsfaber ,

Thank you so much for looking into this!

The physical thermostat is never "off." In the summer, its Mode is Cool; in the winter, its Mode is Heat. The thermostat State will transition from "idle" to "Heat" but its Mode is always "Heat" in these examples.

I was able to capture debug log entries in my original post, but I re-enabled debug logging to see if I can capture more examples.

The idea that a 5 second response is required and failing seems important. That would explain why I saw the same issue with different thermostats and may indicate a physical networking delay that manifests the issue only intermittently.

Thank you again - will report back here with more info as soon as I have it.

e

nielsfaber commented 7 months ago

I just released v3.3.0 of the scheduler component, which implements a different procedure to handle the 'heat' command: 1) The hvac_mode of the climate entity will be set to heat (this is skipped if the hvac_mode is already heat) 2) A 50 seconds delay is started. During the delay will be checked whether the climate entity has updated to hvac_mode=heat. If this occurs, the delay is stopped. 3) The temperature setpoint is set to the programmed value.

I think this improves behaviour for thermostats which take more than 5 seconds to process the command to change the hvac_mode. I think you will still see a short jump in the setpoint in the history graph when the mode is changed, since this is behaviour of the thermostat internally. But the scheduler should directly correct it to the value defined by the schedule.

I would like to ask all to update to the new version and test it in your local setup. Please share your (hopefully improved) experiences.

github-actions[bot] commented 6 months ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days

gloseem commented 5 months ago

Thanks Niels, Been running the new version for a few weeks now and the issue hasn't recurred.

Huge help! thanks again

e