Thermostat Scheduler Miss

gregwkeller · July 3, 2019, 9:46pm

I have 5 Thermostats (ugh) that Are setup identically. I setup Thermostat Scheduler to change the setpoints Day Evening and Night in case someone changes them. In the couple days I've been running it I have spotted it miss on some but not all of the thermostats:

If I click into the schedule and back out, it sets correctly. Any hints on what to look for in the logs?

EDIT: For clarity, this was a couple hours into the "Day" schedule and the other thermostats were at 75F cooling setpoint.

gregwkeller · July 4, 2019, 3:07am

Tonight it didn't change until it saw me look!

It appears to have tried at 8:37PM and then again when I looked at 9:55... Oddly it tried the other one twice at 8:37. Maybe a queue getting stuck until I bump around? I'm guessing multiple thermostats isn't very common config for a HE, so I may be straying too far from the beaten path.

dev:3852019-07-03 09:55:16.217 pm infoThermostat - Window thermostatSetpoint was set to 77.9°F

dev:3852019-07-03 09:55:16.213 pm infoThermostat - Window coolingSetpoint was set to 77.9°F

dev:3862019-07-03 08:37:16.784 pm infoThermostat - Lobby thermostatSetpoint was set to 77.9°F

dev:3862019-07-03 08:37:16.781 pm infoThermostat - Lobby coolingSetpoint was set to 77.9°F

dev:3852019-07-03 08:37:11.779 pm infoThermostat - Window thermostatSetpoint was set to 78.0°F

dev:3852019-07-03 08:37:11.773 pm infoThermostat - Window coolingSetpoint was set to 78.0°F

dev:3862019-07-03 08:37:02.172 pm infoThermostat - Lobby thermostatSetpoint was set to 78.0°F

dev:3862019-07-03 08:37:02.171 pm infoThermostat - Lobby coolingSetpoint was set to 78.0°F

gregwkeller · July 14, 2019, 2:10am

It's switched to night mode....

But the thermostat's aren't set to the Night set points....

But if I click in and out of the Set heating/cooling schedule box....

.... It basically updates itself immediately.

How do I troubleshoot why this isn't reliably triggering?

bravenel · July 14, 2019, 2:30am

First thing to do is to look at the thermostat itself, and see if it's set correctly or not. Also, you can look at its events (device detail page at the top). See if it got the event it was supposed to get.

And, you can do the same thing with the app. Go to its app status page (gear icon) and look at its events. Those are first steps.

gregwkeller · July 14, 2019, 3:00am

Definitely was wrong at the thermostat too, I noticed because it kicked on when it shouldn't have needed to.

Here's the relevant snippets from the relevant logs that I can find... IF I am interpreting them correctly the situation is:

at 8:35pm mode manager declared it night time based on sunset
at 8:35pm the app says the setpoint should be switched to 78F
at 9:03 the system logs report the setpoint is still at 75F, and the cooling kicks on which caught my attention
at ~9:07pm I start looking at the app page as pasted above, the app logs that the settings should be 78F
at 9:08pm I click through to the setting and out without changing anything, and the system finally get's the thermostat set.
I've had this happen multiple times with multiple thermostats and thought maybe it was coincidence at first. This definitely seems to be a case of "to look at it is to change it" IRL.

Logs:
System Event saw it turned to Night mode at 8:35pm:

mode	Ana Lark Center is now in Night mode	Night	LOCATION_MODE_CHANGE	2019-07-13 08:35:00.274 PM CDT
sunsetTime		2019-07-15T01:34:00.000Z	API	2019-07-13 08:35:00.170 PM CDT
sunset		true	API	2019-07-13 08:35:00.049 PM CDT

The app log shows reports at 8:35 before I checked with the correct settings, but the thermostat doesn't actually get it until later when I look around 9:07:

ThermoScheduler	Mode Schedule: Night	Cooling Setpoint 78.0	2019-07-13 09:35:08.015 PM CDT
ThermoScheduler	Mode Schedule: Night	Heating Setpoint 65.0	2019-07-13 09:35:07.990 PM CDT
ThermoScheduler	Mode Schedule: Night	Cooling Setpoint 78.0	2019-07-13 09:08:42.772 PM CDT
ThermoScheduler	Mode Schedule: Night	Heating Setpoint 65.0	2019-07-13 09:08:42.747 PM CDT
ThermoScheduler	Mode Schedule: Night	Cooling Setpoint 78.0	2019-07-13 09:08:35.696 PM CDT
ThermoScheduler	Mode Schedule: Night	Heating Setpoint 65.0	2019-07-13 09:08:35.675 PM CDT
ThermoScheduler	Mode Schedule: Night	Cooling Setpoint 78.0	2019-07-13 09:07:00.183 PM CDT
ThermoScheduler	Mode Schedule: Night	Heating Setpoint 65.0	2019-07-13 09:07:00.160 PM CDT
ThermoScheduler	Mode Schedule: Night	Cooling Setpoint 78.0	2019-07-13 08:35:00.812 PM CDT
ThermoScheduler	Mode Schedule: Night	Heating Setpoint 65.0	2019-07-13 08:35:00.673 PM CDT
ThermoScheduler	Mode Schedule: Evening	Cooling Setpoint 75.0	2019-07-13 06:44:52.750 PM CDT

The logs show the setpoint was still 74.9F at 9:03pm here....
dev:3862019-07-13 09:08:37.085 pm infoThermostat - Lobby coolingSetpoint was set to 78.0°F

dev:3862019-07-13 09:08:37.029 pm infoThermostat - Lobby heatingSetpoint was set to 65.0°F

dev:3862019-07-13 09:03:30.606 pm infoThermostat - Lobby thermostatSetpoint was set to 74.9°F

dev:3862019-07-13 09:03:30.579 pm infoThermostat - Lobby thermostatOperatingState is cooling

dev:3862019-07-13 09:03:30.052 pm infoThermostat - Lobby thermostatSetpoint was set to 74.9°F

dev:3862019-07-13 09:03:30.018 pm infoThermostat - Lobby thermostatOperatingState is pending cool

dev:3862019-07-13 08:31:29.562 pm infoThermostat - Lobby thermostatOperatingState is idle

dev:3862019-07-13 08:31:15.027 pm infoThermostat - Lobby thermostatOperatingState is fan only

dev:3862019-07-13 08:15:56.313 pm infoThermostat - Lobby thermostatSetpoint was set to 74.9°F

dev:3862019-07-13 08:15:56.267 pm infoThermostat - Lobby thermostatOperatingState is cooling

dev:3862019-07-13 08:15:55.234 pm infoThermostat - Lobby thermostatSetpoint was set to 74.9°F

dev:3862019-07-13 08:15:55.155 pm infoThermostat - Lobby thermostatOperatingState is pending cool

bravenel · July 14, 2019, 3:09am

It's better if you use screenshots instead of copy/paste for logs. What about the thermostat device logs. What you're showing pretty much lets Thermostat Scheduler off the hook. It's logging that it set the thermostat. So the question is what became of that. Device logs...

Find those on the thermostat device detail page at the top, click on Events.

gregwkeller · July 14, 2019, 3:17am

Thermostat log saw nothing until 9:08pm....

Very odd.

StephenH · July 14, 2019, 12:25pm

@mike.maxwell @bravenel I think this may be part of what caused me to change from a CT101 Radio Thermostat to a Zen Thermostat only to find out that I have the same issues of the thermostat failing to adjust. The symptoms sound very familiar.

gregwkeller · July 14, 2019, 12:33pm

I've noticed it on my Zen and Centralite Thermostat well FWIW
" * endpointId: 01

application: 13
model: Zen-01
manufacturer: Zen Within
lastRunningMode: cool"

" * endpointId: 01

application:
model: 3157100-E
manufacturer: Centralite
lastRunningMode: cool"

bravenel · July 14, 2019, 3:51pm

Could you show a screenshot of the app events for Thermostat Scheduler from around 8:35 pm.

Also, be sure that Logging is turned on for the thermostat, and keep a Logs page (tab) open. We want to see the logs the thermostat driver puts out as well as the events.

gregwkeller · July 14, 2019, 7:48pm

I think this is what you mean....

I enabled debug logging on that thermostat just now. I'll try and catch it with the debug on if it happens tonight...

Strange...
Noticed the "System Events" says it's "Day"

But the Logs annotation listing "Mode Manager Evening".... even though the log says it's day...

and The Mode Manager App agrees it's Day....

bravenel · July 14, 2019, 8:07pm

We're pretty much down to trying to understand why the command that is sent by Thermostat Scheduler (TS) at 8:35 is not being received or processed correctly by the driver for the thermostat. Which driver is this?

The event you showed above at 8:35 signifies that TS sent the command to change the setPoint. But, we know that didn't happen. We will just keep narrowing down the analysis until we figure it out.

gregwkeller · July 14, 2019, 8:24pm

This particular miss is happening on a "Zen Thermostat" driver. I've also seen it happen with a different Centralite thermostat using the "Generic Zigbee Thermostat" driver.

gregwkeller · July 15, 2019, 1:39am

They all went to 78F right on cue tonight. As they say, a watched pot never boils.

gregwkeller · July 15, 2019, 1:58am

Curiously, here's another case where the state of the Thermostats is not consistant:

Notice the False condition in the test to turn off my fans when both AC units are idle? It should be true, since both AC units are actually idle. Stale cache somewhere maybe?

I'm losing confidence in HE's logic or mine. it's a toss up at the moment.

App Log....

Thermostat - Window log....

Thermostat - Lobby log....

And the main log...

gregwkeller · July 15, 2019, 2:38am

OK, I deleted the Thermostat - Lobby completely, detached it from the network, and recreated it.

So maybe the problem is somewhere in the logic in multiple devices on the same line (where I am an outlier relative to most HE deployments)?

gregwkeller · July 15, 2019, 2:48am

I noticed an extra "all" in the False statement here....

So I deleted and recreated that line and it seems better now....

gregwkeller · July 15, 2019, 3:42am

I noticed the "Event Subscriptions" was only subscribed to three events for the "Thermostat - Window" when there were 2 thermostats on each trigger event line. I broke them out to 1 per line and now I have 5 subscriptions for each thermostat.