Action at $nextsunset executing twice

siwilson · 2017-12-28 09:53:33 UTC

I have a simple piston to activate curtains at 9:00AM and at 30 minutes before $nextsunset every day. The 9:00AM action works great, but the $nextsunset one has started executing twice. I wondered if this is because $nextsunset changes after the job is scheduled and because my execution is 30 mins before $nextsunset, the the next job gets scheduled for the same day.

27/12/2017, 15:29:28 +137ms
+0ms ╔Received event [Home].time = 1514388569267 with a delay of -1131ms
+122ms ║RunTime Analysis CS > 19ms > PS > 39ms > PE > 65ms > CE
+124ms ║Runtime (40585 bytes) successfully initialized in 39ms (v0.2.100.20171211) (123ms)
+125ms ║╔Execution stage started
+161ms ║║Executed physical command [Lounge Curtain Motor].off() (21ms)
+162ms ║║Executed [Lounge Curtain Motor].off (22ms)
+169ms ║║Comparison (boolean) true is (boolean) false = false (2ms)
+170ms ║║Condition #30 evaluated false (5ms)
+171ms ║║Condition group #19 evaluated false (state did not change) (6ms)
+181ms ║║Condition #18 evaluated false (6ms)
+182ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+184ms ║╚Execution stage complete. (59ms)
+186ms ║Setting up scheduled job for Thu, Dec 28 2017 @ 9:00:00 AM GMT (in 63031.677s), with 1 more job pending
+192ms ╚Event processed successfully (193ms)
27/12/2017, 15:28:59 +79ms
+0ms ╔Received event [Home].time = 1514388540000 with a delay of -921ms
+121ms ║RunTime Analysis CS > 19ms > PS > 40ms > PE > 62ms > CE
+124ms ║Runtime (40587 bytes) successfully initialized in 40ms (v0.2.100.20171211) (122ms)
+124ms ║╔Execution stage started
+132ms ║║Comparison (time) 55739209 happens_daily_at (time) 32400000 = false (0ms)
+133ms ║║Condition #8 evaluated false (2ms)
+133ms ║║Cancelling statement #8’s schedules…
+136ms ║║Requesting time schedule wake up at Thu, Dec 28 2017 @ 9:00:00 AM GMT
+142ms ║║Comparison (time) 55739217 happens_daily_at (datetime) 1514390340000 = true (0ms)
+143ms ║║Time restriction check passed
+144ms ║║Condition #2 evaluated true (7ms)
+145ms ║║Cancelling statement #2’s schedules…
+149ms ║║Requesting time schedule wake up at Thu, Dec 28 2017 @ 3:29:00 PM GMT
+151ms ║║Condition group #9 evaluated true (state did not change) (20ms)
+151ms ║║Condition group #1 evaluated true (state did not change) (22ms)
+156ms ║║Comparison (boolean) true is (boolean) true = true (1ms)
+157ms ║║Condition #29 evaluated true (4ms)
+158ms ║║Condition group #28 evaluated true (state did not change) (5ms)
+160ms ║║Cancelling statement #4’s schedules…
+183ms ║║Executed physical command [Lounge Curtain Motor].on() (21ms)
+184ms ║║Executed [Lounge Curtain Motor].on (22ms)
+187ms ║║Executed virtual command [Lounge Curtain Motor].wait (0ms)
+187ms ║║Requesting a wake up for Wed, Dec 27 2017 @ 3:29:29 PM GMT (in 30.0s)
+192ms ║╚Execution stage complete. (68ms)
+194ms ║Setting up scheduled job for Wed, Dec 27 2017 @ 3:29:29 PM GMT (in 29.995s), with 2 more jobs pending
+200ms ╚Event processed successfully (200ms)
27/12/2017, 15:28:28 +152ms
+1ms ╔Received event [Home].time = 1514388509433 with a delay of -1281ms
+109ms ║RunTime Analysis CS > 17ms > PS > 30ms > PE > 62ms > CE
+112ms ║Runtime (40585 bytes) successfully initialized in 30ms (v0.2.100.20171211) (110ms)
+113ms ║╔Execution stage started
+148ms ║║Executed physical command [Lounge Curtain Motor].off() (17ms)
+149ms ║║Executed [Lounge Curtain Motor].off (19ms)
+157ms ║║Comparison (boolean) true is (boolean) false = false (1ms)
+159ms ║║Condition #30 evaluated false (6ms)
+160ms ║║Condition group #19 evaluated false (state did not change) (8ms)
+170ms ║║Condition #18 evaluated false (6ms)
+171ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+175ms ║╚Execution stage complete. (62ms)
+177ms ║Setting up scheduled job for Wed, Dec 27 2017 @ 3:29:00 PM GMT (in 31.672s), with 1 more job pending
+183ms ╚Event processed successfully (183ms)
27/12/2017, 15:27:59 +84ms
+1ms ╔Received event [Home].time = 1514388480000 with a delay of -916ms
+106ms ║RunTime Analysis CS > 17ms > PS > 32ms > PE > 57ms > CE
+109ms ║Runtime (40586 bytes) successfully initialized in 32ms (v0.2.100.20171211) (107ms)
+110ms ║╔Execution stage started
+119ms ║║Comparison (time) 55679201 happens_daily_at (time) 32400000 = false (0ms)
+121ms ║║Cancelling condition #8’s schedules…
+121ms ║║Condition #8 evaluated false (4ms)
+122ms ║║Cancelling statement #8’s schedules…
+125ms ║║Requesting time schedule wake up at Thu, Dec 28 2017 @ 9:00:00 AM GMT
+132ms ║║Comparison (time) 55679212 happens_daily_at (datetime) 1514390340000 = true (1ms)
+133ms ║║Time restriction check passed
+134ms ║║Condition #2 evaluated true (7ms)
+135ms ║║Cancelling statement #2’s schedules…
+140ms ║║Requesting time schedule wake up at Wed, Dec 27 2017 @ 3:29:00 PM GMT
+142ms ║║Condition group #9 evaluated true (state did not change) (25ms)
+143ms ║║Condition group #1 evaluated true (state did not change) (27ms)
+150ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+151ms ║║Condition #29 evaluated true (5ms)
+152ms ║║Condition group #28 evaluated true (state did not change) (7ms)
+154ms ║║Cancelling statement #4’s schedules…
+343ms ║║Executed physical command [Lounge Curtain Motor].on() (186ms)
+344ms ║║Executed [Lounge Curtain Motor].on (188ms)
+348ms ║║Executed virtual command [Lounge Curtain Motor].wait (1ms)
+349ms ║║Requesting a wake up for Wed, Dec 27 2017 @ 3:28:29 PM GMT (in 30.0s)
+355ms ║╚Execution stage complete. (246ms)
+357ms ║Setting up scheduled job for Wed, Dec 27 2017 @ 3:28:29 PM GMT (in 29.992s), with 2 more jobs pending
+364ms ╚Event processed successfully (363ms)
27/12/2017, 09:00:28 +132ms
+1ms ╔Received event [Home].time = 1514365229327 with a delay of -1195ms
+118ms ║RunTime Analysis CS > 19ms > PS > 39ms > PE > 59ms > CE
+120ms ║Runtime (40584 bytes) successfully initialized in 39ms (v0.2.100.20171211) (119ms)
+121ms ║╔Execution stage started
+158ms ║║Executed physical command [Lounge Curtain Motor].off() (21ms)
+159ms ║║Executed [Lounge Curtain Motor].off (22ms)
+165ms ║║Comparison (boolean) true is (boolean) false = false (1ms)
+166ms ║║Cancelling condition #30’s schedules…
+167ms ║║Condition #30 evaluated false (6ms)
+168ms ║║Cancelling condition #19’s schedules…
+169ms ║║Condition group #19 evaluated false (state changed) (7ms)
+177ms ║║Condition #18 evaluated false (6ms)
+178ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+181ms ║╚Execution stage complete. (60ms)
+182ms ║Setting up scheduled job for Wed, Dec 27 2017 @ 3:28:00 PM GMT (in 23251.686s), with 1 more job pending
+189ms ╚Event processed successfully (189ms)
27/12/2017, 08:59:59 +100ms
+1ms ╔Received event [Home].time = 1514365200000 with a delay of -900ms
+148ms ║RunTime Analysis CS > 19ms > PS > 47ms > PE > 82ms > CE
+151ms ║Runtime (40590 bytes) successfully initialized in 47ms (v0.2.100.20171211) (149ms)
+152ms ║╔Execution stage started
+164ms ║║Comparison (time) 32399261 happens_daily_at (time) 32400000 = true (1ms)
+166ms ║║Time restriction check passed
+167ms ║║Cancelling condition #8’s schedules…
+169ms ║║Condition #8 evaluated true (7ms)
+170ms ║║Cancelling statement #8’s schedules…
+173ms ║║Requesting time schedule wake up at Thu, Dec 28 2017 @ 9:00:00 AM GMT
+176ms ║║Condition group #9 evaluated true (state did not change) (15ms)
+177ms ║║Condition group #1 evaluated true (state did not change) (17ms)
+184ms ║║Comparison (boolean) true is (boolean) true = true (1ms)
+185ms ║║Cancelling condition #29’s schedules…
+186ms ║║Condition #29 evaluated true (7ms)
+187ms ║║Cancelling condition #28’s schedules…
+188ms ║║Condition group #28 evaluated true (state changed) (9ms)
+190ms ║║Cancelling statement #4’s schedules…
+221ms ║║Executed physical command [Lounge Curtain Motor].on() (26ms)
+222ms ║║Executed [Lounge Curtain Motor].on (28ms)
+226ms ║║Executed virtual command [Lounge Curtain Motor].wait (0ms)
+227ms ║║Requesting a wake up for Wed, Dec 27 2017 @ 9:00:29 AM GMT (in 30.0s)
+233ms ║╚Execution stage complete. (81ms)
+236ms ║Setting up scheduled job for Wed, Dec 27 2017 @ 9:00:29 AM GMT (in 29.992s), with 2 more jobs pending
+242ms ╚Event processed successfully (242ms)

bobbles · 2017-12-28 10:05:48 UTC

What happens if you use the presets.
i.e.
At 9:00
OR
30 minutes to Sunset.

siwilson · 2017-12-28 10:11:01 UTC

OK, made that change and will see what happens later today. Why do you think it would make a difference?

Thanks

Si

bobbles · 2017-12-28 10:17:04 UTC

I really don’t know. Just thought it might be worth giving it a try.

ady624 · 2017-12-28 12:31:44 UTC

Known bug. Sunset time keeps shifting up these days in the Northern emisphere. As it is scheduled a day ahead, at execution time the next evening, the sunset time has shifted about one minute up, making the piston reschedule again for one minute later, hence the double run. I will try and fix it as soon as possible.

siwilson · 2017-12-29 14:57:46 UTC

Thanks for the reply. Not sure if you fixed anything, but the action triggered correctly yesterday.

siwilson · 2018-01-01 10:39:02 UTC

Spoke too soon. It seems that Sunset did not change that day, but has on subsequent days

I have added a temporary fix with an additional action 60 mins before sunset that just does a 10 second wait.

michicago · 2018-01-02 14:23:53 UTC

Looking at your piston, I think it would work if you used $sunset rather than $nextSunset. You’re not basing your action on tomorrow’s sunset (which is what the next prefix points to).

siwilson · 2018-01-02 14:50:10 UTC

Based on previous advice I change to use the preset of “sunset”, but it didn’t help. Prior to sunset, sunset and nextsunset are the same anyway. its only after sunset and before midnight that they are different.

michicago · 2018-01-02 14:58:41 UTC

Ah, gotcha. In that case, if I want to limit piston executions I usually do it with a variable. You could do it by adding one more IF to your piston

Define Variable LastRun (integer)

Add to your original IF statement:
AND if LastRun is different than $day

Add to the ‘then’ portion of your piston:
IF time is 30 minutes before $sunset
Set variable LastRun to $day

Today, when the piston executes it’ll set LastRun to 2 since it’s the 2nd of January. If the piston were to run again, the “AND LastRun is different than $day” would evaluate false and your piston wouldn’t repeat.

siwilson · 2018-01-02 15:10:33 UTC

Yes, that would work as well. My dummy run 30 mins before I really want it to run seems to cure it as a temporary measure. Ady flagged it as a bug he plans to fix anyway.