Piston not executing completely

[phani]

1) Give a description of the problem
I have a piston that is supposed to turn on 2 lights in the front every day at sunset and turn them off at 10:35 PM. It has been working flawlessly for 6 months but it suddenly stopped working correctly since 3 days. Only some steps are executed - only one light turns on, the other does not and they both do not turn off. Please help?

2) What is the expected behaviour?
Piston execution completes fully. Both lights turn on. Porch light at sunset and Garage light 30 minutes after sunset. Both lights turn off at 10:35 PM.

3) What is happening/not happening?
Piston is not executing completely

4) Post a Green Snapshot of the piston

5) Attach logs after turning logging level to Full
11/4/2019, 10:35:34 PM +251ms
+0ms ╔Received event [Home].execute = recovery with a delay of 55ms
+100ms ║RunTime Analysis CS > 19ms > PS > 44ms > PE > 37ms > CE
+102ms ║Runtime (39770 bytes) successfully initialized in 44ms (v0.3.110.20191009) (101ms)
+103ms ║╔Execution stage started
+133ms ║║Comparison (time) 81334358 happens_daily_at (datetime) 1572907260000 = false (0ms)
+135ms ║║Condition #2 evaluated false (28ms)
+136ms ║║Cancelling statement #2’s schedules…
+139ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 5:41:00 PM EST
+142ms ║║Condition group #1 evaluated false (state did not change) (35ms)
+146ms ║║Comparison (time) 81334395 happens_daily_at (time) 81300000 = false (0ms)
+148ms ║║Condition #20 evaluated false (4ms)
+149ms ║║Cancelling statement #20’s schedules…
+152ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 10:35:00 PM EST
+154ms ║║Condition group #19 evaluated false (state did not change) (10ms)
+157ms ║╚Execution stage complete. (54ms)
+159ms ║Setting up scheduled job for Tue, Nov 5 2019 @ 5:41:00 PM EST (in 68725.591s), with 1 more job pending
+165ms ╚Event processed successfully (165ms)
11/4/2019, 6:12:00 PM +403ms
+1ms ╔Received event [Home].execute = recovery with a delay of 75ms
+107ms ║RunTime Analysis CS > 22ms > PS > 51ms > PE > 33ms > CE
+109ms ║Runtime (39764 bytes) successfully initialized in 51ms (v0.3.110.20191009) (107ms)
+110ms ║╔Execution stage started
+139ms ║║Comparison (time) 65520517 happens_daily_at (datetime) 1572907260000 = false (1ms)
+141ms ║║Cancelling condition #2’s schedules…
+142ms ║║Condition #2 evaluated false (27ms)
+143ms ║║Cancelling statement #2’s schedules…
+146ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 5:41:00 PM EST
+148ms ║║Cancelling condition #1’s schedules…
+149ms ║║Condition group #1 evaluated false (state changed) (35ms)
+154ms ║║Comparison (time) 65520555 happens_daily_at (time) 81300000 = false (1ms)
+155ms ║║Condition #20 evaluated false (3ms)
+157ms ║║Cancelling statement #20’s schedules…
+159ms ║║Requesting time schedule wake up at Mon, Nov 4 2019 @ 10:35:00 PM EST
+162ms ║║Condition group #19 evaluated false (state did not change) (11ms)
+165ms ║╚Execution stage complete. (55ms)
+167ms ║Setting up scheduled job for Mon, Nov 4 2019 @ 10:35:00 PM EST (in 15779.431s), with 1 more job pending
+176ms ╚Event processed successfully (176ms)
11/4/2019, 5:41:11 PM +213ms
+1ms ╔Received event [Home].time = 1572907260000 with a delay of 11213ms
+88ms ║RunTime Analysis CS > 20ms > PS > 43ms > PE > 25ms > CE
+91ms ║Runtime (39773 bytes) successfully initialized in 43ms (v0.3.110.20191009) (89ms)
+91ms ║╔Execution stage started
+118ms ║║Comparison (time) 63671309 happens_daily_at (datetime) 1572907260000 = true (0ms)
+119ms ║║Time restriction check passed
+120ms ║║Cancelling condition #2’s schedules…
+121ms ║║Condition #2 evaluated true (24ms)
+121ms ║║Cancelling statement #2’s schedules…
+125ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 5:41:00 PM EST
+127ms ║║Cancelling condition #1’s schedules…
+127ms ║║Condition group #1 evaluated true (state changed) (31ms)
+129ms ║║Cancelling statement #3’s schedules…
+144ms ║║Executed physical command [Porch Light].setLevel([100]) (10ms)
+145ms ║║Executed [Porch Light].setLevel (12ms)
+153ms ║║Executed physical command [Porch Light].on() (6ms)
+154ms ║║Executed [Porch Light].on (8ms)
+156ms ║║Cancelling statement #6’s schedules…
+159ms ║║Executed virtual command wait (0ms)
+160ms ║║Requesting a wake up for Mon, Nov 4 2019 @ 6:11:11 PM EST (in 1800.0s)
+165ms ║╚Execution stage complete. (74ms)
+167ms ║Setting up scheduled job for Mon, Nov 4 2019 @ 6:11:11 PM EST (in 1799.995s), with 2 more jobs pending
+175ms ╚Event processed successfully (175ms)

[Rizlah]

maybe try pausing the piston then restarting it, I have heard some people complain about this sort of stuff since DST kicked in. Might not fix it for you but worth a try

[phani]

Unfortunately, this started happening before DST. Its been a problem since Halloween night I believe (I am not making this up!).

[Rizlah]

still worth trying pausing and restarting, its like rebooting your laptop if it starts acting up. Might just clear out any “gremlins” or “ghosts”

[phani]

Will do and check today. Thanks!

[Pantheon]

I’m not at my computer right now, but you might try setting the TCP (Task Cancellation Policy). Waits sometimes interfere with expected execution.

[GaWd]

I’ll restart my pistons, but I am having the same issue with my pistons as well. They turn on, and then they are not turning off. They have all worked flawlessly for many months with no changes, but in the last few days (before DST, so not related), they’ve begun working, to turn on, but not to turn off.

[TonyD]

I’ve been having very similar problems in pretty much the exact same time frame. I’ve been waiting to do my own post until I feel like I really understand the problem. So far, it seems like each day I get different results, meaning I don’t see the exact same problems with the exact same pistons every day. I have eight “happens daily at” pistons that have worked flawlessly for the past year, and just last week they started freaking out. Some of them use sunset as the trigger, some of them use exact times and one uses a “wait 5 minutes” trigger. I noticed it Halloween night, but that was also my first night home after being out of town since Sunday. My wife didn’t notice any issues while I was gone.

I tried pausing and restarting all of them. I tried going into edit mode and then saving them (without changing anything). Does not seem to have helped. I also verified that my ST Hub is showing the right time, time zone and sunset/sunrise.

I do notice that the logs always seem to have “Received event [Home].execute = recovery” in them when they fail, but I haven’t been able to figure out if that means anything useful or what to do about it.

[phani]

Interesting. So in my case, where do I set the TCP (to “Never cancel tasks” I believe)? On the with…do statement after the wait? Or on if statements itself at the top level where i check the times?

Note that one problem is the garage light does not turn on at sunset. But the other issue is that both lights do not turn off at 10:35 either, and there are no waits within that if block.

Sorry this is the first time I paid attention to these advanced task settings!

[WCmore]

Only some steps are executed - only one light turns on, the other does not and they both do not turn off. Please help?

There is a pattern in your logs regarding your two failed events (Garage on at 6:12 and both off at 10:35) :
╔Received event [Home].execute = recovery

By the time the recovery kicked in, all of your conditions were returning “false”, so no commands were sent.

If you turn on Trace, there will be new numbers in your piston that correlate to the "Condition #'s" found in your log.

[phani]

Here it is:

[WCmore]

Yup, that was it. Notice the new greyed out numbers at the end of each line. They match up with the numbers in your log.

IE:
Condition #2 evaluated false
means it was no longer $sunset at the time.

[phani]

I set the TCP to Never for 2 actions within the if statements. I will report what happens tonight.
But again, this was working fine for a while till last week.

Not sure what that recovery means, I dont have logs from before to compare and see if that came out all the time.

[WCmore]

When SmartThings is behaving, a “recovery” usually means there’s too much commotion in the household at that time…

…but with the latest hiccups, I suspect that SmartThings is not processing in a timely fashion…

---

The former can be a pain to troubleshoot…
The latter is totally out of our control…

[phani]

The piston worked fine last night. The logs are no longer showing “recovery”. I am going to chalk this up to a SmartThings platform issue. Will remove the TCP settings that I set earlier.

[GaWd]

Hopefully this isn’t a distraction to Phani’s issues, but both of my malfunctioning pistons contained inline wait statements in the initial if blocks. I had seen when I was implementing them that an if block like this:

if [condition]
then do [thing],
[thing 2],
[thing 3]

Was a frowned-upon practice, but it always worked. In my case, I believe it said something like:

turn on light 1,
set to 100%,
wait 4 hours,
turn off

Yesterday, I changed both to have the turn on if block separate from the wait/turn off if blocks. Both pistons are operating as expected.

I do hope things stabilize in general with Smartthings. Had a bunch of issues not related to my shoddy programming lately.

[phani]

I didn’t know that this was a frowned upon practice till the last couple of days. I still have 2 pistons that do this too, turn on a light when a door opens, wait and turn it off, all within the same initial If block. And they stopped working in the last 1 week. I did not yet pay attention to them since I wanted this other piston to work first.

I guess, when the platform works well, it masks bad piston programming. Latency at the platform level exposes these sort of issues.

[Pantheon]

Latency CREATES issues!