Gradually turn on lights.

[gwp1]

I updated to latest-21337-b535732 last night before heading off to sleep. I have a ruleset that checks for phone charging, mode evening, and room-assistant home. The system then waits five minutes and flips to mode night and announces it has done so via Echo devices.

At 05:30 ET each morning the system shifts to mode day.

However...

Last night MSR went thru the paces but mode evening never switched to mode night. Multiple attempts including reboots of MSR and Hubitat, no change.

This morning, instead of mode day it went back to mode evening which isn't supposed to trigger until sunset. This is confirmed across MSR, H-A, and Hubitat.

I'd missed the 21336 update and went from 21332 to 21337. I'll be log diving after coffee is ready.

Updated title to reflect what the issue seems to actually be.

[gwp1]

@gwp1 This is interesting: can't have the house in mode evening so I hit the reset icon on the day mode ruleset Rule ID: rule-kmfo3pz8. It shows I took the action:

...but I don't see any reference to that action in the log nor did the mode change to day.

This is the log since 0529 ET.

[latest-21337]2021-12-04T15:05:29.018Z <Rule:NOTICE> Rule#rule-kmfo3pz8 resetting!
[latest-21337]2021-12-04T15:05:29.020Z <Rule:NOTICE> Rule#rule-kmfo3pz8 stopping rule
[latest-21337]2021-12-04T15:05:29.021Z <Rule:5:Rule.js:743> Rule#rule-kmfo3pz8 acquiring semaphore
[latest-21337]2021-12-04T15:05:29.023Z <Rule:5:Rule.js:746> Rule#rule-kmfo3pz8 semaphore acquired; releasing timer
[latest-21337]2021-12-04T15:05:29.024Z <Rule:5:Rule.js:746> Rule#rule-kmfo3pz8 semaphore acquired; unsubscribing from condition dependencies
[latest-21337]2021-12-04T15:05:29.036Z <Rule:5:Rule.js:748> Rule#rule-kmfo3pz8 saving states
[latest-21337]2021-12-04T15:05:29.041Z <Rule:5:Rule.js:752> Rule#rule-kmfo3pz8 stopped
[latest-21337]2021-12-04T15:05:29.041Z <Rule:NOTICE> Rule Rule#rule-kmfo3pz8 stopped
[latest-21337]2021-12-04T15:05:29.044Z <Rule:NOTICE> Rule#rule-kmfo3pz8 restarting after reset
[latest-21337]2021-12-04T15:05:29.045Z <Rule:5:Rule.js:716> Rule#rule-kmfo3pz8 start(), awaiting semaphore
[latest-21337]2021-12-04T15:05:29.051Z <Rule:5:Rule.js:724> Rule#rule-kmfo3pz8 restored states: trig=(null), rule=(null)
[latest-21337]2021-12-04T15:05:29.052Z <Rule:5:Rule.js:724> Rule#rule-kmfo3pz8 subscribing to dependencies
[latest-21337]2021-12-04T15:05:29.053Z <Rule:INFO> Rule#rule-kmfo3pz8 (Day mode:  05:30 ET) started
[latest-21337]2021-12-04T15:05:29.054Z <Rule:5:Rule.js:728> Rule#rule-kmfo3pz8 start() dependencies resolved, performing initial evaluation
[latest-21337]2021-12-04T15:05:29.055Z <Rule:5:Rule.js:1005> Rule#rule-kmfo3pz8 (Day mode:  05:30 ET) evaluate() acquiring mutex
[latest-21337]2021-12-04T15:05:29.056Z <Rule:5:Rule.js:1009> Rule#rule-kmfo3pz8._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T15:05:29.057Z <Rule:5:Rule.js:1013> Rule#rule-kmfo3pz8 update rate is 0/min limit 60/min
[latest-21337]2021-12-04T15:05:29.058Z <Rule:5:Rule.js:936> Rule#rule-kmfo3pz8 evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T15:05:29.065Z <Rule:5:Rule.js:1689> cond cond6xza990 evaluation state (null)->false
[latest-21337]2021-12-04T15:05:29.069Z <Rule:5:Rule.js:1689> cond condkmfo3pz8 evaluation state (null)->true
[latest-21337]2021-12-04T15:05:29.074Z <Rule:5:Rule.js:1689> cond condeadfqgq evaluation state (null)->true
[latest-21337]2021-12-04T15:05:29.075Z <Rule:5:Rule.js:1689> cond trig evaluation state (null)->false
[latest-21337]2021-12-04T15:05:29.079Z <Rule:5:Rule.js:1033> Rule#rule-kmfo3pz8._evaluate() trigger state now false (was (null))
[latest-21337]2021-12-04T15:05:29.080Z <Rule:5:Rule.js:1035> Rule#rule-kmfo3pz8._evaluate() constraints state true
[latest-21337]2021-12-04T15:05:29.081Z <Rule:5:Rule.js:1041> Rule#rule-kmfo3pz8 trigger conditions not met
[latest-21337]2021-12-04T15:05:29.081Z <Rule:5:Rule.js:1042> Rule#rule-kmfo3pz8 rule state changed, was (undefined) now false
[latest-21337]2021-12-04T15:05:29.082Z <Rule:INFO> Day mode:  05:30 ET (Rule#rule-kmfo3pz8) RESET!
[latest-21337]2021-12-04T15:05:29.083Z <Rule:5:Rule.js:1044> Rule#rule-kmfo3pz8 rule state now false, changed true
[latest-21337]2021-12-04T15:05:38.996Z <Rule:5:Rule.js:793> Rule#rule-grpoix7c2a Office On/Off requesting eval; entity-changed from Entity#hubitat>51
[latest-21337]2021-12-04T15:05:38.997Z <Rule:5:Rule.js:1005> Rule#rule-grpoix7c2a (Office On/Off) evaluate() acquiring mutex
[latest-21337]2021-12-04T15:05:38.998Z <Rule:5:Rule.js:1009> Rule#rule-grpoix7c2a._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T15:05:38.999Z <Rule:5:Rule.js:1013> Rule#rule-grpoix7c2a update rate is 4/min limit 60/min
[latest-21337]2021-12-04T15:05:39.000Z <Rule:5:Rule.js:936> Rule#rule-grpoix7c2a evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T15:05:39.006Z <Rule:5:Rule.js:1033> Rule#rule-grpoix7c2a._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T15:05:39.007Z <Rule:5:Rule.js:1035> Rule#rule-grpoix7c2a._evaluate() constraints state true
[latest-21337]2021-12-04T15:05:39.008Z <Rule:5:Rule.js:1044> Rule#rule-grpoix7c2a rule state now false, changed no
[latest-21337]2021-12-04T15:05:45.991Z <Rule:5:Rule.js:793> Rule#rule-grpoix7c2a Office On/Off requesting eval; entity-changed from Entity#hubitat>51
[latest-21337]2021-12-04T15:05:45.995Z <Rule:5:Rule.js:1005> Rule#rule-grpoix7c2a (Office On/Off) evaluate() acquiring mutex
[latest-21337]2021-12-04T15:05:45.998Z <Rule:5:Rule.js:1009> Rule#rule-grpoix7c2a._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T15:05:46.000Z <Rule:5:Rule.js:1013> Rule#rule-grpoix7c2a update rate is 4/min limit 60/min
[latest-21337]2021-12-04T15:05:46.002Z <Rule:5:Rule.js:936> Rule#rule-grpoix7c2a evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T15:05:46.005Z <Rule:5:Rule.js:1033> Rule#rule-grpoix7c2a._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T15:05:46.007Z <Rule:5:Rule.js:1035> Rule#rule-grpoix7c2a._evaluate() constraints state true
[latest-21337]2021-12-04T15:05:46.009Z <Rule:5:Rule.js:1044> Rule#rule-grpoix7c2a rule state now false, changed no
[latest-21337]2021-12-04T15:06:02.533Z <Rule:5:Rule.js:793> Rule#rule-kphozuch Upstairs bulb requesting eval; entity-changed from Entity#hubitat>55
[latest-21337]2021-12-04T15:06:02.534Z <Rule:5:Rule.js:793> Rule#rule-komaz8fr Upstairs motion requesting eval; entity-changed from Entity#hubitat>55
[latest-21337]2021-12-04T15:06:02.535Z <Rule:5:Rule.js:1005> Rule#rule-kphozuch (Upstairs bulb) evaluate() acquiring mutex
[latest-21337]2021-12-04T15:06:02.535Z <Rule:5:Rule.js:1005> Rule#rule-komaz8fr (Upstairs motion) evaluate() acquiring mutex
[latest-21337]2021-12-04T15:06:02.536Z <Rule:5:Rule.js:1009> Rule#rule-kphozuch._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T15:06:02.537Z <Rule:5:Rule.js:1013> Rule#rule-kphozuch update rate is 0/min limit 60/min
[latest-21337]2021-12-04T15:06:02.538Z <Rule:5:Rule.js:936> Rule#rule-kphozuch evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T15:06:02.540Z <Rule:5:Rule.js:1033> Rule#rule-kphozuch._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T15:06:02.541Z <Rule:5:Rule.js:1035> Rule#rule-kphozuch._evaluate() constraints state true
[latest-21337]2021-12-04T15:06:02.541Z <Rule:5:Rule.js:1044> Rule#rule-kphozuch rule state now false, changed no
[latest-21337]2021-12-04T15:06:02.545Z <Rule:5:Rule.js:1009> Rule#rule-komaz8fr._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T15:06:02.545Z <Rule:5:Rule.js:1013> Rule#rule-komaz8fr update rate is 0/min limit 60/min
[latest-21337]2021-12-04T15:06:02.546Z <Rule:5:Rule.js:936> Rule#rule-komaz8fr evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T15:06:02.548Z <Rule:5:Rule.js:1033> Rule#rule-komaz8fr._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T15:06:02.549Z <Rule:5:Rule.js:1035> Rule#rule-komaz8fr._evaluate() constraints state true
[latest-21337]2021-12-04T15:06:02.549Z <Rule:5:Rule.js:1044> Rule#rule-komaz8fr rule state now false, changed no
[latest-21337]2021-12-04T15:06:03.376Z <Rule:5:Rule.js:793> Rule#rule-grpoix7c2a Office On/Off requesting eval; timer-trigger from Timer#rule-grpoix7c2a
[latest-21337]2021-12-04T15:06:03.377Z <Rule:5:Rule.js:1005> Rule#rule-grpoix7c2a (Office On/Off) evaluate() acquiring mutex
[latest-21337]2021-12-04T15:06:03.378Z <Rule:5:Rule.js:1009> Rule#rule-grpoix7c2a._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T15:06:03.379Z <Rule:5:Rule.js:1013> Rule#rule-grpoix7c2a update rate is 3/min limit 60/min
[latest-21337]2021-12-04T15:06:03.380Z <Rule:5:Rule.js:936> Rule#rule-grpoix7c2a evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T15:06:03.381Z <Rule:5:Rule.js:1033> Rule#rule-grpoix7c2a._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T15:06:03.382Z <Rule:5:Rule.js:1035> Rule#rule-grpoix7c2a._evaluate() constraints state true
[latest-21337]2021-12-04T15:06:03.383Z <Rule:5:Rule.js:1044> Rule#rule-grpoix7c2a rule state now false, changed no

[toggledbits]

I just tested mode sensitivity, which I also had done before the build, and it's working as expected. So that part is fine. The log shows "Day mode" rule is going to Reset state, so unless your action is in the Reset reaction, I wouldn't expect it to log the change you seem to anticipate. You haven't shown the rules or reactions, so I have no way of judging what it will do or whether what I can see it doing is right. Show your work, please! Also check your host time zone settings. Logs are Zulu (UTC), not ET, and that would account for a five hour difference in host time vs log time, normally (standard time).

http://your-reactor-ip:8111/diag/sun

Also look at the rule detail panel any time you are troubleshooting logic. Your log snippets don't show any actions being run at all for rule-kmfo3pz8, just the rule eval/update to Reset state. Logging of actions in HubitatController is currently unconditional, so if any action was being sent, it would be in the logs (regardless of log level).

[gwp1]

@toggledbits The host time is currently 12/4/2021, 10:41:24 AM offset -300 minutes from UTC, which lines up to log timestamps of 15:xx:xx.

This ruleset hasn't changed since MSR came online months ago so I'm loathe to point to that, esp since it's across multiple modes.

Searching the log for this ruleset shows it first appearing at that RESET! line.

I've rolled back to 21332 and retested. Mode day did not kick over as expected. Given this has worked flawlessly with this build I'm digging further. Right now it appears like the house never moved to mode night even though all the actions (lights off, announcement made, unlocked locks locked) happened.

How far back does MSR retain logs time-wise?

[toggledbits]

@gwp1 said in Modes not changing correctly since 21337:

How far back does MSR retain logs time-wise?

As far as your log rotation allows.

Can you go back to 21337 and show the result of the rule detail/status panel?

Also, make sure to check the case of all mode setting actions. Mode names are case-sensitive in Hubitat ( day =/= Day ), so if they don't match, the action won't work. When testing in conditions, make sure the test is case-insensitive (it is in the rule you've shown, so that's good).

[gwp1]

@toggledbits I just moved back to 21337 a moment ago. I cannot seem to get the house into mode night atm. Troubleshooting this as my thinking now is that the house, though doing all the actions (and I repeated that just now), doesn't actually going into mode night anymore.

[toggledbits]

Try "Night" (capital N)... case matters to Hubitat

[gwp1]

@toggledbits When it is time for the house to go into night there is an Alexa routine that flips a virtual switch. This is the sole trigger and the result is the running of a Reaction.

This has been unchanged.

At the end of the reaction is a :10 delay and the virtual switch flips back off again (for next time.) That's it. Nothing fancy. All of these steps are working except for the mode actually changing to night.

This has worked for MONTHS untouched. I'm literally watching it step thru here:

[gwp1]

@gwp1 Ok, this is very odd. I can change the mode in this reaction to any other mode but night and it works. Put it back to night as the outcome and nada.

[toggledbits]

This post is deleted!

[toggledbits]

@gwp1 Please show the entity detail for the "Mode" entity (Entities list).

Also, try setting "Night" from the Entities list actions. And grab logs for the action if it doesn't change.

[gwp1]

@toggledbits This is odd. Wouldn't I expect to see all the modes listed under x_hubitat_sys_mode.modes={"Day":1}?

Tried setting Night from the Entities list actions. Nada.

[latest-21337]2021-12-04T16:45:03.111Z <Rule:5:Rule.js:793> Rule#rule-kphozuch Upstairs bulb requesting eval; entity-changed from Entity#hubitat>55
[latest-21337]2021-12-04T16:45:03.112Z <Rule:5:Rule.js:793> Rule#rule-komaz8fr Upstairs motion requesting eval; entity-changed from Entity#hubitat>55
[latest-21337]2021-12-04T16:45:03.113Z <Rule:5:Rule.js:1005> Rule#rule-kphozuch (Upstairs bulb) evaluate() acquiring mutex
[latest-21337]2021-12-04T16:45:03.114Z <Rule:5:Rule.js:1005> Rule#rule-komaz8fr (Upstairs motion) evaluate() acquiring mutex
[latest-21337]2021-12-04T16:45:03.120Z <Rule:5:Rule.js:1009> Rule#rule-kphozuch._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T16:45:03.121Z <Rule:5:Rule.js:1013> Rule#rule-kphozuch update rate is 0/min limit 60/min
[latest-21337]2021-12-04T16:45:03.122Z <Rule:5:Rule.js:936> Rule#rule-kphozuch evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T16:45:03.124Z <Rule:5:Rule.js:1033> Rule#rule-kphozuch._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T16:45:03.125Z <Rule:5:Rule.js:1035> Rule#rule-kphozuch._evaluate() constraints state true
[latest-21337]2021-12-04T16:45:03.127Z <Rule:5:Rule.js:1044> Rule#rule-kphozuch rule state now false, changed no
[latest-21337]2021-12-04T16:45:03.131Z <Rule:5:Rule.js:1009> Rule#rule-komaz8fr._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T16:45:03.133Z <Rule:5:Rule.js:1013> Rule#rule-komaz8fr update rate is 0/min limit 60/min
[latest-21337]2021-12-04T16:45:03.134Z <Rule:5:Rule.js:936> Rule#rule-komaz8fr evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T16:45:03.136Z <Rule:5:Rule.js:1033> Rule#rule-komaz8fr._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T16:45:03.137Z <Rule:5:Rule.js:1035> Rule#rule-komaz8fr._evaluate() constraints state true
[latest-21337]2021-12-04T16:45:03.139Z <Rule:5:Rule.js:1044> Rule#rule-komaz8fr rule state now false, changed no
[latest-21337]2021-12-04T16:45:46.427Z <Rule:5:Rule.js:793> Rule#rule-grpoix7c2a Office On/Off requesting eval; entity-changed from Entity#hubitat>51
[latest-21337]2021-12-04T16:45:46.429Z <Rule:5:Rule.js:1005> Rule#rule-grpoix7c2a (Office On/Off) evaluate() acquiring mutex
[latest-21337]2021-12-04T16:45:46.431Z <Rule:5:Rule.js:1009> Rule#rule-grpoix7c2a._evaluate() mutex acquired, evaluating
[latest-21337]2021-12-04T16:45:46.432Z <Rule:5:Rule.js:1013> Rule#rule-grpoix7c2a update rate is 2/min limit 60/min
[latest-21337]2021-12-04T16:45:46.433Z <Rule:5:Rule.js:936> Rule#rule-grpoix7c2a evaluateExpressions() with 0 expressions
[latest-21337]2021-12-04T16:45:46.436Z <Rule:5:Rule.js:1033> Rule#rule-grpoix7c2a._evaluate() trigger state now false (was false)
[latest-21337]2021-12-04T16:45:46.437Z <Rule:5:Rule.js:1035> Rule#rule-grpoix7c2a._evaluate() constraints state true
[latest-21337]2021-12-04T16:45:46.439Z <Rule:5:Rule.js:1044> Rule#rule-grpoix7c2a rule state now false, changed no
[latest-21337]2021-12-04T16:45:46.673Z <HubitatController:null> HubitatController#hubitat final action path for x_hubitat_sys_mode.set on Entity#hubitat>sys_mode: http://192.168.1.214/apps/api/14/modes/Night

[toggledbits]

According to the entity, the only mode that exists on the hub is Day. Log in to your hub and check the Modes screen. If that agrees, something happened to your hub (firmware upgrade to latest new version recently?).

[gwp1]

@toggledbits

Latest release to 2.3.0.115 on Hubitat. Rolling back to .113 to see what happens.

[gwp1]

@gwp1 Rolled back to .113, saw this:

When the restore was done it was in Evening because that's where it was when the release was deployed and backup taken.

Did a Tools > Restart on MSR to ensure everything was synced and now I see this again:

[toggledbits]

Are you on their latest firmware?

[gwp1]

@toggledbits Well I was until apparently an hour ago lol Seems there's .116 out now. Also, rolling back apparently doesn't restore the old firmware to .113 like I thought it would. I'm still on .115. Guess I'll fail forward to .116.

[gwp1]

@gwp1 On Hubitat's latest, .116. No change.

Following my Rule#1 of troubleshooting, "what changed?" I rolled back MSR to 21332 (because I'd just updated to 21337) just in case and now I see this:

Things are behaving as they should. Using the Entities menu I triggered mode night and it flipped over (only to flip back to day as it should because it's day time - but I watched it three times visibly flip to the correct mode.)

[toggledbits]

Yup, and I think I see the issue... stay tuned...

[toggledbits]

OK. 21338