RM not tracking Sunset-offset?

[bravenel]

You shouldn’t have to hitting update on the location page. So skip that part tomorrow and let me see what happens.

March 5 is when we released 702, and there were some timezone related changes in that build. It’s possible that something got messed up, but hard to tell at the moment. My own mode change happens right at sunset, and it has changed as expected each day by a minute or so, including since March 5.

[Tony]

OK ; I forgot to mention that I also have a Simple Lighting Rule set up to trigger the same lamp at the exact sunset-5 min. time (I had set up the RM to control the light as a circumvention for the original sunset bug in Simple Lighting). I accidentally looked at Simple Lighting rules’ schedule instead of RM’s schedule when I made that observation.

When i discovered that, I did note that RM’s schedule was still set for the incorrect time so obviously updating the location page had no effect on it. I did update to .704 and will report back.

Eoit: I also remember posting (on the Sunday of DST changeover) that my RM rule’s schedule was not updated-- and it did’t update until I refreshed the rule; that’s what bumped it to the 6:54 time: DST: Need to refresh RM rule using sunset -offset even if location times correct

[Tony]

@bravenel, it looks like Simple Lighting may be involved with this scenario; perhaps having a redundant RM trigger with an identical turn on time may be relevant?

After the update last evening to .704 here is what I see:

Hubitat Location page shows sunset at 7:04 PM.
Scheduled event for RM ‘light on at sunset - 5 minutes’ correctly shows a scheduled turn on event for 18:59:00:

Scheduled Jobs

Handler	Next Run Time	Prev Run Time	Status	Schedule
timeHandler	Sat Mar 17 18:59:00 EDT 2018		PENDING	0 59 18 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018		PENDING	29 5 2 * * ?

Here’s where things go astray:
Scheduled events for the redundant Simple Lighting app (‘Turn on at sunset -5 min’ along with a ‘Turn off at sunrise’) shows:

Scheduled Jobs

Handler	Next Run Time	Prev Run Time	Status	Schedule
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
doAntiAction	Sun Mar 18 07:04:00 EDT 2018	Sat Mar 17 07:04:00 EDT 2018	PENDING	0 4 7 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
doAction	Sat Mar 17 18:59:00 EDT 2018		PENDING	0 59 18 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018		PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018	Sat Mar 17 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleAtTime	Sun Mar 18 02:05:29 EDT 2018		PENDING	29 5 2 * * ?

Note that there is a scheduled Simple Lighting ‘doaction’ for the correct time (18:59) as well as the correct ‘doantiaction’. Could all the extra Simple Lighting schedules for 02:05:29 be a side effect of having both RM and Simple Lighting schedule an event for the exact same time, and could that somehow be the cause of the original ‘stuck’ time symptom due to some subsequent scheduling malfunction?

I’ll wait for your input before trying anything obvious (like deleting a redundant time-coincident schedule, or removing/reinstalling anything). I’m the guy with the 93 custom commands in Rule Machine that I’d like to avoid having to re-create if possible.

[bjcowles]

Reading @Tony’s post made me look at my sunrise/sunset app and I have over 600 scheduleAtTime events pending. Mine has been firing at the correct times, but 600 seems a little odd.

[bravenel]

@Tony

I’ll wait for your input before trying anything obvious (like deleting a redundant time-coincident schedule, or removing/reinstalling anything). I’m the guy with the 93 custom commands in Rule Machine that I’d like to avoid having to re-create if possible.

We found a bug in Simple Lighting last night. It will get fixed in the next release, and we may do that sooner rather than later.

[bravenel]

The scheduling bug in Simple Lighting has been fixed and released in 1.0.3.705.

Hub Update 1.0.3.705

Hubitat Elevation Software Update 1.0.3.705 is now available. Please note, the process takes about a minute to download (depending on your Internet connection) and extract the hub update, and from one to two minutes to perform the update after you click Update. We recommend that you periodically download a backup of your setup from the Settings page, Backup and Restore. Changes from 1.0.3.704 Bug Fixes: Simple Lighting: Sunrise/Sunset scheduling Hubitat™ Safety Monitor: Alert lights bein…

[Tony]

Thank you!

[bjcowles]

@bravenel Just wanted to give you a heads-up. After updating to 705, my Sunrise/Sunset scheduling completed 600 times.

But logged an error for each one.

Not sure if it's important, but thought I'd pass it along.

[Tony]

Interesting. Something is still amiss. I also updated to .705 and after doing so deleted my original SL 'turn on at sunset-offset and also turn off at sunrise' rule and recreated it. Here is a shot of the new Simple Lighting rule:

This morning app status shows this:

Scheduled Jobs

Handler	Next Run Time	Prev Run Time	Status	Schedule
scheduleSunrise	Mon Mar 19 02:05:29 EDT 2018	Sun Mar 18 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
doAction	Sun Mar 18 18:59:00 EDT 2018		PENDING	Once
scheduleSunset	Mon Mar 19 02:05:29 EDT 2018	Sun Mar 18 02:05:29 EDT 2018	PENDING	29 5 2 * * ?

which shows the correct 'doAction' schedule, but the 'doAntiAction' is not scheduled (you can see in the screenshot of the app that 'ON' is selected for 'also turn off at sunrise'. Unfortunately I didn't have logging running at the time; maybe I didn't see the redundant scheduling errors because the SL rule was newly created (maybe they will manifest after another round through the scheduler).

[bjcowles]

I deleted and rebuilt the original SL rule. I do not have the multiple scheduling events and have a blank doAntiAction, which is to be expected. We’ll see what happens at 02:05.

[EdwardN]

If you want to troubleshoot sunrise/sunset events you can change your location to match an approaching sunrise/sunset but that’s a lot of work.

[ogiewon]

Just a guess… Maybe when the ON action fires, it will schedule the OFF action?

[Tony]

It’s possible; but it appears that both sunrise and sunset get scheduled at 2:05:29 AM every day.

[bravenel]

@Tony

which shows the correct ‘doAction’ schedule, but the ‘doAntiAction’ is not scheduled (you can see in the screenshot of the app that ‘ON’ is selected for ‘also turn off at sunrise’. Unfortunately I didn’t have logging running at the time; maybe I didn’t see the redundant scheduling errors because the SL rule was newly created (maybe they will manifest after another round through the scheduler).

Since you did this after sunrise, tomorrow's sunrise event is not yet scheduled. Today's sunset event is scheduled. At 2:05 tomorrow morning, scheduleSunrise will run (so will schedule Sunset), and schedule tomorrow morning's sunrise action.

[bravenel]

@bjcowles

Not sure if it’s important, but thought I’d pass it along.

Did you go into your SL rule and click Done? You need to do that for it to schedule itself correctly.

[Tony]

Ah ok, I will hang tight (my mind is still trying to unravel the sequencing of events… this stuff isn’t as easy as seems it should be).

[bjcowles]

Yes, I did. That rule has been working for a month without being touched. Like I said above, I deleted and rebuilt it and it looks good so far. We’ll see what happens when it sets the schedule for tommorow.
Thank you Bruce.

[Tony]

The anti-Action Sunrise event (turnoff) didn’t happen at sunrise; no turn-off event was logged for the lamp. Nothing appears to be scheduled for the next sunrise either. Previous to the update I was seeing the both doAntiAction scheduled along with the doAction. Is this feature working for anyone else?

Sunset events are getting scheduled normally, however; and as of the latest update the day to day changes are being propagated to RM rules correctly as well.

Here’s what the Simple Lighting rule for ‘turn off at sunset -6 min with turnoff at sunrise’ looks like this morning (screenshot of the rule is in a prior post; this rule was newly created right after the .705 update was applied on the 17th).

Scheduled Jobs

Handler	Next Run Time	Prev Run Time	Status	Schedule
scheduleSunrise	Tue Mar 20 02:05:29 EDT 2018	Mon Mar 19 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
doAction	Mon Mar 19 19:00:00 EDT 2018		PENDING	Once
scheduleSunset	Tue Mar 20 02:05:29 EDT 2018	Mon Mar 19 02:05:29 EDT 2018	PENDING	29 5 2 * * ?

[bjcowles]

In my case, the antiAction did work this morning and light turned off. My scheduled jobs for the rule look the same as yours.

Handler	Next Run Time	Prev Run Time	Status	Schedule
doAction	Mon Mar 19 19:37:00 EDT 2018		PENDING	Once
scheduleSunrise	Tue Mar 20 02:05:29 EDT 2018	Mon Mar 19 02:05:29 EDT 2018	PENDING	29 5 2 * * ?
scheduleSunset	Tue Mar 20 02:05:29 EDT 2018	Mon Mar 19 02:05:29 EDT 2018	PENDING	29 5 2 * * ?

I’m hoping the doAntiAction gets scheduled at the next 02:05:29 . This might be the way the multiple scheduling events issue was alleviated. I don’t know why your’s didn’t work this am.

[Tony]

Well that’s interesting. Still seems odd that there is no record of the doAntiAction schedule, especially since it appeared before the fix (along with the scores of erroneous scheduled events). I’ll have to dig back into the event log to see if the antiAction fired the first time (Sunday’s sunrise, right after the update). EDIT: no sunrise event happened for the first scheduled sunrise after the rule was installed.