Automation no longer working, was working fine for 2 years

ryuichi88 · 2019-10-29 01:57:15 UTC

1) Give a description of the problem
(Automation no longer working as expected.)

2) What is the expected behaviour?
(Simple automation to turn on and off lights 30 minutes past sunset & turn off lights at sunrise. Been running this piston automation for over 2 years and in the past week it has not been working.)

3) What is happening/not happening?
(I literally just enabled logging as I type this out to you guys, however I notice the automation in the SmartThings app is being triggered properly but the lights don’t actually turn on. I can manually tap the lights within the app and they function properly)

**4) Post a Green Snapshot of the piston

5) Attach logs after turning logging level to Full
10/28/2019, 6:50:33 PM +587ms
+1ms ╔Starting piston… (v0.3.110.20191009)
+1761ms ║╔Subscribing to devices…
+1880ms ║║Subscribing to Front Porch…
+1882ms ║║Subscribing to Guest Room…
+1883ms ║║Subscribing to Office…
+1884ms ║║Subscribing to Side Porch…
+1885ms ║╚Finished subscribing (138ms)
+1959ms ║Comparison (time) 67835498 is_between (time) 1572310980000 … (time) 1572271680000 = true (11ms)
+1960ms ║Time restriction check passed
+2049ms ║Cancelling statement #2’s schedules…
+2065ms ║Requesting time schedule wake up at Tue, Oct 29 2019 @ 7:38:00 AM PDT
+2099ms ║Setting up scheduled job for Tue, Oct 29 2019 @ 7:38:00 AM PDT (in 46044.315s)
+2114ms ╚Piston successfully started (2114ms)

REMOVE BELOW AFTER READING

WCmore · 2019-10-29 02:10:37 UTC

I will come back when I can look at an error in the log… Please also turn on Trace for a new green snapshot as well. (since it helps to make sense of the log)

Food for thought…
This piston only runs twice a day. Once, shortly before sunset (turn on), and once, shortly after sunrise (turn off). With the current wording, it will not run at any other time.

ryuichi88 · 2019-10-29 04:07:39 UTC

Can you shed some light on how to enable trace? Apologies for the stupid questions but I can’t find it under the log options…

Also if you’re still online couldn’t I just set the variables to a time such as now to get the log to output the data?

Thanks!

WCmore · 2019-10-29 04:21:06 UTC

Sure thing. It is located right above the Logs…

temp

(sometimes you may have to press “Test” for it to appear)

In this case, I think it is better to let it happen naturally… (it is only a few more hours)

Please make sure logging level is set to FULL ahead of time.

ryuichi88 · 2019-10-29 04:25:20 UTC

Pressing “test” fixed the issue of trace not appearing

Log setting is confirmed and set to “FULL”.

Thanks Again!

WCmore · 2019-10-29 04:27:15 UTC

No problem at all.

When you capture an error in your log, please post a new green snapshot as well. When you turned on Trace, it adds more info to the JPEG that helps when analyzing the logs

ryuichi88 · 2019-10-29 18:34:31 UTC

I noticed the lights shutoff at the given time so looks like it only fails turning on at sunset.

Log below

10/29/2019, 7:38:59 AM +49ms
+0ms ╔Received event [Rio Hondo].time = 1572359940000 with a delay of -951ms
+118ms ║RunTime Analysis CS > 37ms > PS > 28ms > PE > 53ms > CE
+122ms ║Runtime (37412 bytes) successfully initialized in 28ms (v0.3.110.20191009) (120ms)
+123ms ║╔Execution stage started
+182ms ║║Comparison (time) 27539180 is_between (time) 1572397320000 … (time) 1572358140000 = false (13ms)
+185ms ║║Cancelling condition #2’s schedules…
+186ms ║║Condition #2 evaluated false (56ms)
+187ms ║║Cancelling statement #2’s schedules…
+199ms ║║Requesting time schedule wake up at Tue, Oct 29 2019 @ 5:32:00 PM PDT
+203ms ║║Cancelling condition #1’s schedules…
+204ms ║║Condition group #1 evaluated false (state changed) (74ms)
+208ms ║║Cancelling statement #28’s schedules…
+627ms ║║Executed physical command [Front Porch].off() (414ms)
+629ms ║║Executed [Front Porch].off (418ms)
+658ms ║║Executed physical command [Guest Room].off() (26ms)
+659ms ║║Executed [Guest Room].off (28ms)
+682ms ║║Executed physical command [Office].off() (21ms)
+683ms ║║Executed [Office].off (23ms)
+707ms ║║Executed physical command [Side Porch].off() (22ms)
+708ms ║║Executed [Side Porch].off (24ms)
+711ms ║║Executed virtual command [Front Porch, Guest Room, Office, Side Porch].setState (0ms)
+718ms ║╚Execution stage complete. (596ms)
+727ms ║Setting up scheduled job for Tue, Oct 29 2019 @ 5:32:00 PM PDT (in 35580.225s)
+737ms ╚Event processed successfully (736ms)
10/29/2019, 7:37:59 AM +55ms
+0ms ╔Received event [Rio Hondo].time = 1572359880000 with a delay of -945ms
+104ms ║RunTime Analysis CS > 32ms > PS > 41ms > PE > 31ms > CE
+107ms ║Runtime (37412 bytes) successfully initialized in 41ms (v0.3.110.20191009) (105ms)
+107ms ║╔Execution stage started
+150ms ║║Comparison (time) 27479167 is_between (time) 1572397320000 … (time) 1572358140000 = true (9ms)
+157ms ║║Time restriction check passed
+159ms ║║Condition #2 evaluated true (46ms)
+163ms ║║Cancelling statement #2’s schedules…
+170ms ║║Requesting time schedule wake up at Tue, Oct 29 2019 @ 7:39:00 AM PDT
+172ms ║║Condition group #1 evaluated true (state did not change) (61ms)
+174ms ║║Cancelling statement #3’s schedules…
+459ms ║║Executed physical command [Front Porch].setLevel([100]) (280ms)
+460ms ║║Executed [Front Porch].setLevel (282ms)
+491ms ║║Executed physical command [Guest Room].setLevel([100]) (28ms)
+492ms ║║Executed [Guest Room].setLevel (30ms)
+523ms ║║Executed physical command [Office].setLevel([100]) (30ms)
+524ms ║║Executed [Office].setLevel (32ms)
+551ms ║║Executed physical command [Side Porch].setLevel([100]) (26ms)
+552ms ║║Executed [Side Porch].setLevel (27ms)
+555ms ║║Executed virtual command [Front Porch, Guest Room, Office, Side Porch].setState (1ms)
+557ms ║╚Execution stage complete. (450ms)
+559ms ║Setting up scheduled job for Tue, Oct 29 2019 @ 7:39:00 AM PDT (in 60.387s)
+568ms ╚Event processed successfully (567ms)

WCmore · 2019-10-29 21:49:43 UTC

Excellent! I’ll check back after your 5:32 PM wakeup schedule…

I am curious as to why there is a 1 minute delay in your last log…
There is no WAIT in your piston…

At 7:37:59 AM, Setting up scheduled job for 7:39:00 AM

ryuichi88 · 2019-10-30 09:20:01 UTC

Heres the latest log for sunset. Just arrived at the house and no lights are on even though the automation was ran.

10/29/2019, 5:31:59 PM +73ms
+1ms ╔Received event [Rio Hondo].time = 1572395520000 with a delay of -928ms
+125ms ║RunTime Analysis CS &gt; 28ms &gt; PS &gt; 36ms &gt; PE &gt; 62ms &gt; CE
+129ms ║Runtime (37424 bytes) successfully initialized in 36ms (v0.3.110.20191009) (127ms)
+131ms ║╔Execution stage started
+340ms ║║Comparison (time) 63119215 is_between (time) 1572397320000 .. (time) 1572358140000 = true (18ms)
+342ms ║║Time restriction check passed
+345ms ║║Cancelling condition #2's schedules...
+346ms ║║Condition #2 evaluated true (204ms)
+348ms ║║Cancelling statement #2's schedules...
+362ms ║║Requesting time schedule wake up at Wed, Oct 30 2019 @ 7:39:00 AM PDT
+366ms ║║Cancelling condition #1's schedules...
+368ms ║║Condition group #1 evaluated true (state changed) (226ms)
+371ms ║║Cancelling statement #3's schedules...
+1022ms ║║Executed physical command [Front Porch].setLevel([100]) (642ms)
+1023ms ║║Executed [Front Porch].setLevel (644ms)
+1061ms ║║Executed physical command [Guest Room].setLevel([100]) (37ms)
+1063ms ║║Executed [Guest Room].setLevel (38ms)
+1171ms ║║Executed physical command [Office].setLevel([100]) (105ms)
+1172ms ║║Executed [Office].setLevel (107ms)
+1219ms ║║Executed physical command [Side Porch].setLevel([100]) (45ms)
+1221ms ║║Executed [Side Porch].setLevel (47ms)
+1225ms ║║Executed virtual command [Front Porch, Guest Room, Office, Side Porch].setState (0ms)
+1228ms ║╚Execution stage complete. (1098ms)
+1232ms ║Setting up scheduled job for Wed, Oct 30 2019 @ 7:39:00 AM PDT (in 50819.696s)
+1241ms ╚Event processed successfully (1241ms)
10/29/2019, 11:31:09 AM +671ms
+0ms ╔Received event [Rio Hondo].test = 1572373869671 with a delay of 1ms
+79ms ║RunTime Analysis CS &gt; 14ms &gt; PS &gt; 20ms &gt; PE &gt; 45ms &gt; CE
+82ms ║Runtime (37420 bytes) successfully initialized in 20ms (v0.3.110.20191009) (81ms)
+83ms ║╔Execution stage started
+124ms ║║Comparison (time) 41469759 is_between (time) 1572397320000 .. (time) 1572358140000 = false (12ms)
+126ms ║║Condition #2 evaluated false (38ms)
+129ms ║║Cancelling statement #2's schedules...
+138ms ║║Requesting time schedule wake up at Tue, Oct 29 2019 @ 5:32:00 PM PDT
+142ms ║║Condition group #1 evaluated false (state did not change) (55ms)
+144ms ║║Cancelling statement #28's schedules...
+345ms ║║Executed physical command [Front Porch].off() (194ms)
+346ms ║║Executed [Front Porch].off (196ms)
+380ms ║║Executed physical command [Guest Room].off() (31ms)
+381ms ║║Executed [Guest Room].off (34ms)
+435ms ║║Executed physical command [Office].off() (51ms)
+436ms ║║Executed [Office].off (53ms)
+487ms ║║Executed physical command [Side Porch].off() (48ms)
+488ms ║║Executed [Side Porch].off (50ms)
+491ms ║║Executed virtual command [Front Porch, Guest Room, Office, Side Porch].setState (1ms)
+520ms ║╚Execution stage complete. (437ms)
+523ms ║Setting up scheduled job for Tue, Oct 29 2019 @ 5:32:00 PM PDT (in 21649.807s)
+556ms ╚Event processed successfully (556ms)
10/29/2019, 11:30:45 AM +718ms
+1ms ╔Starting piston... (v0.3.110.20191009)
+255ms ║╔Subscribing to devices...
+342ms ║║Subscribing to Front Porch...
+343ms ║║Subscribing to Guest Room...
+344ms ║║Subscribing to Office...
+346ms ║║Subscribing to Side Porch...
+346ms ║╚Finished subscribing (100ms)
+412ms ║Comparison (time) 41446082 is_between (time) 1572397320000 .. (time) 1572358140000 = false (13ms)
+416ms ║Cancelling statement #2's schedules...
+425ms ║Requesting time schedule wake up at Tue, Oct 29 2019 @ 5:32:00 PM PDT
+447ms ║Setting up scheduled job for Tue, Oct 29 2019 @ 5:32:00 PM PDT (in 21673.835s)
+461ms ╚Piston successfully started (460ms)

I’m not an expert but is there a reason why its showing two previous logs before the evening? I don’t recall running anything at that time hmmmm?

WCmore · 2019-10-30 09:28:37 UTC

The logging looks good actually…

Most bulbs turn on when changing the levels… but there are a few devices that only turn on when the level CHANGES. In other words, try adding a “Turn On” command right before the “Set Level to 100%” command.

Yes, the first:

Was when you last saved the piston… and a few moments later, you pressed the TEST button…

orangebucket · 2019-10-30 09:50:59 UTC

In your previous set of logs you can see the piston ran a minute or so too early in the morning so it set the levels to 100% and scheduled another run for when it should have woken up. On that run it turned the lights off and scheduled another run for the evening.

In this set of logs it looks like at about half past eleven you probably went into edit mode in the piston and then hit ‘save’ to exit (or maybe you paused and restarted). So the piston went through its start up process, subscribed to some devices, and scheduled a run for the evening. Then it looks like you hit the ‘test’ button so it turned the lights off as requested and again scheduled the run for the evening. Your evening run set the levels to 100% and scheduled the next run for the morning.

I would suggest the problem is not with the piston as such, but that setting the level to 100% is not also causing your lights to turn on as it presumably has in the past. I don’t use dimmers so that isn’t an area I pay close attention to.

Ah I see WCmore beat me to it.