Sunset Trigger Ran in the Middle of the Day


#1

1) Give a description of the problem
Piston trigger for sunset ran at 12:46 PM

2) What is the expected behaviour?
This piston has been running normal at sunset for several months

3) What is happening/not happening?
Piston did not run at sunset. It ran in the middle of the day. Not sure if this is just a fluke or a mis-configuration.

4) Post a Green Snapshot of the piston!

5) Attach logs after turning logging level to Full
3/19/2020, 12:46:59 PM +77ms
+1ms ╔Received event [Home].time = 1584636420000 with a delay of -923ms
+135ms ║RunTime Analysis CS > 58ms > PS > 44ms > PE > 32ms > CE
+137ms ║Runtime (37715 bytes) successfully initialized in 44ms (v0.3.110.20191009) (135ms)
+138ms ║╔Execution stage started
+170ms ║║Comparison (time) 46019221 happens_daily_at (time) 1584636420000 = true (0ms)
+171ms ║║Time restriction check passed
+172ms ║║Condition #2 evaluated true (28ms)
+177ms ║║Cancelling statement #2’s schedules…
+182ms ║║Requesting time schedule wake up at Fri, Mar 20 2020 @ 12:47:00 PM EDT
+184ms ║║Condition group #1 evaluated true (state did not change) (41ms)
+186ms ║║Cancelling statement #3’s schedules…
+204ms ║║Executed physical command [Garage Front Light].on() (12ms)
+205ms ║║Executed [Garage Front Light].on (15ms)
+219ms ║║Executed physical command [Garage Side Light].on() (11ms)
+220ms ║║Executed [Garage Side Light].on (13ms)
+233ms ║║Executed physical command [House Front Light].on() (11ms)
+235ms ║║Executed [House Front Light].on (13ms)
+381ms ║║Executed virtual command [Garage Front Light, Garage Side Light, House Front Light].sendSMSNotification (138ms)
+405ms ║╚Execution stage complete. (267ms)
+407ms ║Setting up scheduled job for Fri, Mar 20 2020 @ 4:00:00 AM EDT (in 54780.517s), with 1 more job pending
+414ms ╚Event processed successfully (414ms)
3/19/2020, 3:59:59 AM +79ms
+1ms ╔Received event [Home].time = 1584604800000 with a delay of -921ms
+118ms ║RunTime Analysis CS > 34ms > PS > 43ms > PE > 40ms > CE
+121ms ║Runtime (37715 bytes) successfully initialized in 43ms (v0.3.110.20191009) (117ms)
+122ms ║╔Execution stage started
+144ms ║║Cancelling statement #2’s schedules…
+181ms ║║Requesting time schedule wake up at Thu, Mar 19 2020 @ 12:47:00 PM EDT
+225ms ║╚Execution stage complete. (104ms)
+227ms ║Setting up scheduled job for Thu, Mar 19 2020 @ 12:47:00 PM EDT (in 31620.694s), with 1 more job pending
+234ms ╚Event processed successfully (233ms)
3/18/2020, 6:45:59 PM +77ms
+1ms ╔Received event [Home].time = 1584571560000 with a delay of -923ms
+223ms ║RunTime Analysis CS > 79ms > PS > 112ms > PE > 32ms > CE
+226ms ║Runtime (37717 bytes) successfully initialized in 112ms (v0.3.110.20191009) (223ms)
+226ms ║╔Execution stage started
+262ms ║║Comparison (time) 67559309 happens_daily_at (time) 1584571560000 = true (1ms)
+263ms ║║Time restriction check passed
+264ms ║║Condition #2 evaluated true (32ms)
+269ms ║║Cancelling statement #2’s schedules…
+273ms ║║Requesting time schedule wake up at Thu, Mar 19 2020 @ 6:46:00 PM EDT
+276ms ║║Condition group #1 evaluated true (state did not change) (44ms)
+278ms ║║Cancelling statement #3’s schedules…
+466ms ║║Executed physical command [Garage Front Light].on() (182ms)
+467ms ║║Executed [Garage Front Light].on (184ms)
+482ms ║║Executed physical command [Garage Side Light].on() (12ms)
+482ms ║║Executed [Garage Side Light].on (14ms)
+496ms ║║Executed physical command [House Front Light].on() (12ms)
+497ms ║║Executed [House Front Light].on (14ms)
+509ms ║║Executed virtual command [Garage Front Light, Garage Side Light, House Front Light].sendSMSNotification (7ms)
+536ms ║╚Execution stage complete. (310ms)
+538ms ║Setting up scheduled job for Thu, Mar 19 2020 @ 4:00:00 AM EDT (in 33240.385s), with 1 more job pending
+545ms ╚Event processed successfully (544ms)


#2

That is very strange. The 4 AM run definitely said it would run again at 12:47 and that’s what it did. Does it now show it will run again at sunset? I notice when it scheduled the 12:47 run it also had one more job pending. Definitely seems like a glitch. Your piston looks simple enough and don’t see any issues. Have to see if it happens again tomorrow.


#3

Definitely weird. I would try adding a 12 second WAIT to the 4AM block, followed by a single log to console.

Also, if you need future troubleshooting, please turn on Trace for this piston.


#4

That’s odd. It is like the Sunset was returned in GMT not EDT. Probably worth checking your location in SmartThings in case it has somehow got splattered.


#5

If your real sunset times for Tuesday the 19th was a near match for the minutes highlighted:

pic

… then I am going to agree with @orangebucket


Edit:

Nevermind, I see on the 18th the sun set at 6:45:59 PM.

Good catch, @orangebucket!