search

nielsfaber / scheduler-component

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

Schedule does not consistently apply to thermostat #188

Closed tykeal closed 2 years ago

tykeal commented 2 years ago

Checklist

Card Version

v2.3.3

Component Version

v3.2.7

Bug description

After a restart of HA schedules (usually) work for my thermostat for 1 day. After that, then they don't always apply properly.

My thermostat is a Z-Wave Radio Thermostat CT101 model and presents itself as two thermostats (one for heating, one for cooling and they aren't labeled for which is which!)

I have a schedule configured to do the following against both thermostats

00:00 - 09:00: Regulate 70 - 77 09:00 - 20:30: Regulate 74 - 77 20:30 - 24:00: Regulate 70 - 77

This schedule usually works correctly for 1 day after a restart of HA, after that the schedule seems to be sporadic in working correctly.

Steps to reproduce

I get no logs when it fails, even when in debug mode! It just silently fails as such I have yet to figure out a way to force this to reproduce.

Additional info

I've ended up having to do my own automation and disable this to get it working right now. What I've found in my working on the automation is that if I have the climate.set_temperature call configured to also set the HVAC mode then most times the call will either fail or it works but it doesn't get applied. Additionally, I've had to add a 30 second delay (might work with a lower delay) and then I reapply the same settings. This seems to work 100% of the time now, it is, however, a lot more fiddly than using a nice GUI to set this!

The biggest issue seems to be setting HVAC mode to heat_cool (regulate) at the same time as setting the temperature high and low. I have yet to do any testing related to setting to just heat or cool mode and also setting the target set point at the same time.

nielsfaber commented 2 years ago

After a restart of HA schedules (usually) work for my thermostat for 1 day. After that, then they don't always apply properly.

That's very odd. Scheduler is programmed to keep repeating the same thing, so I have no clue what causes this.

My thermostat is a Z-Wave Radio Thermostat CT101 model and presents itself as two thermostats (one for heating, one for cooling and they aren't labeled for which is which!)

I have a schedule configured to do the following against both thermostats

00:00 - 09:00: Regulate 70 - 77 09:00 - 20:30: Regulate 74 - 77 20:30 - 24:00: Regulate 70 - 77

The 'regulate' action should only be available for climate entities which have (combined) heating+cooling capabilities, i.e. work as air conditioning. Climate entities have a property 'hvac_modes' which should include 'heat_cool' if this is the case. Could you go to developer tools -> states and make a screenshot of the properties of this climate entity?

This schedule usually works correctly for 1 day after a restart of HA, after that the schedule seems to be sporadic in working correctly.

You could enable debug logging by adding to configuration.yaml

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

It would be useful to see if scheduler triggers at consistent times, also the service which is executed is displayed here. Could you share the loggings in a couple of days?

Please give scheduler a second chance, I'm sure we can fix this 😉

tykeal commented 2 years ago

I've just added the logger statement. When I was initially troubleshooting I would just dynamically enable it after a restart (they don't happen every day so I could get away with it).

I'll disable my current automation and re-enable the scheduler for a couple of days. Hopefully we'll get the root cause sorted out.

tykeal commented 2 years ago

Just a quick update. I enabled the schedule after I added the logger statement and did a restart. Interestingly I saw some debug statements about only checking one of the two thermostats I've got assigned:

2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.timer] Timer of 28f0cd set for 2022-03-07 09:00:00-08:00
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.switch] Schedule 28f0cd is starting in a timeslot, proceed with actions
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3_2
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 06:44:43 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Finished execution of actions

The two climate devices attached to this schedule are:

climate.thermostat_h3 and climate.thermostat_h3_2

h3_2 seems to be (from most of my testing) to be the one that controls the cooling side of the thermostat. My schedule is supposed to go into effect in ~37 minutes so I'll give an update when it fires.

nielsfaber commented 2 years ago

As the loggings state, the climate entity was already set to 'regulate' mode (hvac_mode = heat_cool) with the same min/max temperatures as scheduled, so there was nothing to do. Please check your schedule configuration against the properties of your climate entity (see Developer Tools -> states) to verify if this is indeed the case.

tykeal commented 2 years ago 
2022-03-07 09:00:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer 28f0cd has reached slot 1
2022-03-07 09:00:00 DEBUG (MainThread) [custom_components.scheduler.switch] Schedule 28f0cd is triggered, proceed with actions
2022-03-07 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3
2022-03-07 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Postponing next action for 5 seconds
2022-03-07 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-07 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Postponing next action for 5 seconds
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3_2
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-07 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Finished execution of actions
2022-03-07 09:01:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer of 28f0cd set for 2022-03-07 20:30:00-08:00

Ok, there's the log from the firing of the schedule (which worked). Admittedly, as I've stated before, it always seems to work after a restart. At least the first schedule change. We'll see about the follow on changes later today and I'll keep updating.

But yes, I see that it's doing an HVAC change separate from the set_temperature change, so that's good at least!

nielsfaber commented 2 years ago

From these logs you can see that scheduler has to perform the set_temperature action twice within 5 seconds (on each entity). Which suggests that either:

  1. Your climate entity does not expose the target_temp_low / target_temp_high properties (current setpoints)
  2. The climate entity takes more than 5 seconds to process the first request, and the target_temp_low / target_temp_high properties are not updated yet
  3. The climate entity internally changes its target_temp_low / target_temp_high properties on changing of the hvac_mode (the first set_temperature action attempts to set the hvac_mode simultaneously)

In either case something is wrong with the climate entity itself. Hopefully you can pinpoint which of these cases is applicable.

tykeal commented 2 years ago

I know I've seen in my personal testing that sometimes it takes longer than 5 seconds to process the first request. The weird thing is that when it does, it almost always resets the targets back to what they were before the request. It's why I've got a delay of 30 seconds in my (currently disabled) automation.

I'll post again later after the next scheduled change. I usually manage to get through a full 24 hours after a restart of it working correctly before things stop working reliably.

nielsfaber commented 2 years ago

The other day I shared a script here which can be used to ‘mimic’ the same sequence as scheduler performs while allowing the delay to be varied: https://github.com/nielsfaber/scheduler-component/issues/181#issuecomment-1059825398 This might help you to find a timing which does work consistently. If desired you could even call the script from scheduler (via customize you can add a field for the delay) so you can try it out for a week before drawing conclusions.

tykeal commented 2 years ago

So far so good. But we haven't hit a full 24 hour cycle yet.

Here's the 20:30 to 00:00 run (which worked)

2022-03-07 20:30:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer 28f0cd has reached slot 2
2022-03-07 20:30:00 DEBUG (MainThread) [custom_components.scheduler.switch] Schedule 28f0cd is triggered, proceed with actions
2022-03-07 20:30:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3
2022-03-07 20:30:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Postponing next action for 5 seconds
2022-03-07 20:30:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-07 20:30:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Postponing next action for 5 seconds
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3_2
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-07 20:30:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Finished execution of actions
2022-03-07 20:31:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer of 28f0cd set for 2022-03-07 23:59:59-08:00

and then the 00:00 - 09:00 run (which did nothing as expected since it's really just a continuation of the 20:30 - 00:00 run

2022-03-07 23:59:59 DEBUG (MainThread) [custom_components.scheduler.timer] Timer of 28f0cd set for 2022-03-08 00:00:00-08:00
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer 28f0cd has reached slot 0
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.switch] Schedule 28f0cd is triggered, proceed with actions
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3_2
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-08 00:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Finished execution of actions
2022-03-08 00:01:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer of 28f0cd set for 2022-03-08 09:00:00-08:00

I see there's another HA update, but I'm not going to pick it up right now (I usually do right away). I want to see if we can capture this issue I've been experiencing.

As for the script. I may give it a try if I continue to have these issues.

tykeal commented 2 years ago

And 09:00 - 20:30 schedule fired just a little bit ago. Succeeded

2022-03-08 09:00:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer 28f0cd has reached slot 1
2022-03-08 09:00:00 DEBUG (MainThread) [custom_components.scheduler.switch] Schedule 28f0cd is triggered, proceed with actions
2022-03-08 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3
2022-03-08 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Postponing next action for 5 seconds
2022-03-08 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-08 09:00:00 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Postponing next action for 5 seconds
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_hvac_mode on entity climate.thermostat_h3_2
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Action has no effect, skipping
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Executing service climate.set_temperature on entity climate.thermostat_h3_2
2022-03-08 09:00:05 DEBUG (MainThread) [custom_components.scheduler.actions] [28f0cd]: Finished execution of actions
2022-03-08 09:01:00 DEBUG (MainThread) [custom_components.scheduler.timer] Timer of 28f0cd set for 2022-03-08 20:30:00-08:00

For once it seems to be working correctly. I'll keep an eye on it and try to avoid restarting my HA for now. I'll give an update again in a few days or if/when it acts up so I can capture the logs.

I wonder if some of the latest updates to the ZWave-JS component have fixed issues that I may have been having.

tykeal commented 2 years ago

Ok, I've watched this for a few days and everything is working correctly now. I'm not certain what all it was causing the issues. I've had many different updates of HA since I first noticed it, but haven't done any since we started monitoring it. I'll leave the debug logging turned on and if I start encountering the issue again I'll build up a better report. In the meantime, thanks for sticking with me on this. I'll close it out.