Piston stops prematurely

[markplewis]

1) Give a description of the problem
I have a piston that should loop a specific number of times. It works, but erratically. Sometimes the piston will loop 4 times, sometimes 7, sometimes 3 before it stops executing. The piston should stop when a counter reaches 21, and while the variable is incrementing correctly the piston stops executing well before the variable gets set to 21.

I watched the piston run many times and it was accurately scheduling the next iteration of the loop but then crapped out each time. Each time it stops, I see the following message in the log but don’t know what it means or if it’s indicative of something I did wrong when I created the piston:

Received event [Home].execute = recovery with a delay of 202ms

2) What is the expected behavior?
Piston should execute a loop for a specific number of times and then stop.

3) What is happening/not happening?
The piston stops executing even though the variable that controls the loop has not been reached. The number of times the loop is executed before the piston ends varies each time the piston executes.

**4) Post a Green Snapshot of the piston![image|45x37]

**5) Attach any logs (From [ST IDE]

9/7/2018, 10:02:55 AM +233ms
+0ms ╔Received event [Home].execute = recovery with a delay of 78ms
+10193ms ║RunTime Analysis CS > 23ms > PS > 10141ms > PE > 31ms > CE
+10195ms ║Piston waited at a semaphore for 10095ms
+10197ms ║Runtime (44770 bytes) successfully initialized in 10141ms (v0.3.108.20180906) (10196ms)
+10198ms ║╔Execution stage started
+10212ms ║║Condition #2 evaluated false (8ms)
+10213ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+10223ms ║║Condition #18 evaluated false (7ms)
+10225ms ║║Condition group #17 evaluated false (state did not change) (8ms)
+10227ms ║╚Execution stage complete. (29ms)
+10229ms ╚Event processed successfully (10230ms)

9/7/2018, 10:02:55 AM +507ms
+1ms ╔Received event [Home].execute = recovery with a delay of 190ms
+121ms ║RunTime Analysis CS > 22ms > PS > 68ms > PE > 30ms > CE
+123ms ║Runtime (44691 bytes) successfully initialized in 68ms (v0.3.108.20180906) (121ms)
+125ms ║╔Execution stage started
+142ms ║║Condition #2 evaluated false (10ms)
+143ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+152ms ║║Condition #18 evaluated false (6ms)
+154ms ║║Condition group #17 evaluated false (state did not change) (7ms)
+157ms ║╚Execution stage complete. (32ms)
+158ms ╚Event processed successfully (158ms)

9/7/2018, 10:02:55 AM +121ms
+0ms ╔Received event [Home].execute = recovery with a delay of 211ms
+95ms ║RunTime Analysis CS > 17ms > PS > 53ms > PE > 25ms > CE
+97ms ║Runtime (44683 bytes) successfully initialized in 53ms (v0.3.108.20180906) (96ms)
+98ms ║╔Execution stage started
+113ms ║║Cancelling condition #2’s schedules…
+114ms ║║Condition #2 evaluated false (10ms)
+115ms ║║Cancelling condition #1’s schedules…
+118ms ║║Condition group #1 evaluated false (state changed) (12ms)
+128ms ║║Cancelling condition #18’s schedules…
+130ms ║║Condition #18 evaluated false (7ms)
+131ms ║║Cancelling condition #17’s schedules…
+132ms ║║Condition group #17 evaluated false (state changed) (11ms)
+136ms ║╚Execution stage complete. (38ms)
+137ms ╚Event processed successfully (137ms)

9/7/2018, 9:59:56 AM +138ms
+1ms ╔Received event [Home].time = 1536335997470 with a delay of -1332ms
+107ms ║RunTime Analysis CS > 19ms > PS > 59ms > PE > 29ms > CE
+110ms ║Runtime (44688 bytes) successfully initialized in 59ms (v0.3.108.20180906) (108ms)
+111ms ║╔Execution stage started
+140ms ║║Calculating (string) Door to garage is open. Message + (string) 6 >> (string) Door to garage is open. Message 6
+144ms ║║Calculating (string) Door to garage is open. Message 6 + (string) of 20. >> (string) Door to garage is open. Message 6 of 20.
+259ms ║║Executed virtual command sendPushNotification (110ms)
+274ms ║║Comparison (enum) open is (string) open = true (2ms)
+276ms ║║Condition #22 evaluated true (12ms)
+282ms ║║Comparison (integer) 6 is_less_than (integer) 21 = true (2ms)
+284ms ║║Condition #23 evaluated true (6ms)
+285ms ║║Condition group #21 evaluated true (state did not change) (23ms)
+293ms ║║Comparison (integer) 6 is_less_than_or_equal_to (integer) 19 = true (2ms)
+295ms ║║Condition #25 evaluated true (7ms)
+297ms ║║Condition group #24 evaluated true (state did not change) (10ms)
+300ms ║║Cancelling statement #30’s schedules…
+308ms ║║Calculating (integer) 6 + (integer) 1 >> (integer) 7
+315ms ║║Executed virtual command setVariable (4ms)
+322ms ║║Executed virtual command wait (1ms)
+336ms ║║Requesting a wake up for Fri, Sep 7 2018 @ 10:00:56 AM MDT (in 60.0s)
+350ms ║╚Execution stage complete. (239ms)
+353ms ║Setting up scheduled job for Fri, Sep 7 2018 @ 10:00:56 AM MDT (in 59.992s)
+363ms ╚Event processed successfully (363ms)

9/7/2018, 9:58:57 AM +136ms
+1ms ╔Received event [Home].time = 1536335938261 with a delay of -1126ms
+193ms ║RunTime Analysis CS > 89ms > PS > 77ms > PE > 28ms > CE
+196ms ║Runtime (44688 bytes) successfully initialized in 77ms (v0.3.108.20180906) (194ms)
+198ms ║╔Execution stage started
+230ms ║║Calculating (string) Door to garage is open. Message + (string) 5 >> (string) Door to garage is open. Message 5
+235ms ║║Calculating (string) Door to garage is open. Message 5 + (string) of 20. >> (string) Door to garage is open. Message 5 of 20.
+263ms ║║Executed virtual command sendPushNotification (22ms)
+278ms ║║Comparison (enum) open is (string) open = true (2ms)
+280ms ║║Condition #22 evaluated true (13ms)
+287ms ║║Comparison (integer) 5 is_less_than (integer) 21 = true (2ms)
+289ms ║║Condition #23 evaluated true (8ms)
+291ms ║║Condition group #21 evaluated true (state did not change) (24ms)
+301ms ║║Comparison (integer) 5 is_less_than_or_equal_to (integer) 19 = true (2ms)
+303ms ║║Condition #25 evaluated true (7ms)
+304ms ║║Condition group #24 evaluated true (state did not change) (10ms)
+308ms ║║Cancelling statement #30’s schedules…
+318ms ║║Calculating (integer) 5 + (integer) 1 >> (integer) 6
+324ms ║║Executed virtual command setVariable (3ms)
+331ms ║║Executed virtual command wait (1ms)
+333ms ║║Requesting a wake up for Fri, Sep 7 2018 @ 9:59:57 AM MDT (in 60.0s)
+342ms ║╚Execution stage complete. (144ms)
+344ms ║Setting up scheduled job for Fri, Sep 7 2018 @ 9:59:57 AM MDT (in 59.991s)
+356ms ╚Event processed successfully (355ms)

9/7/2018, 9:57:57 AM +153ms
+1ms ╔Received event [Home].time = 1536335878333 with a delay of -1181ms
+922ms ║RunTime Analysis CS > 149ms > PS > 746ms > PE > 27ms > CE
+925ms ║Runtime (44691 bytes) successfully initialized in 746ms (v0.3.108.20180906) (921ms)
+926ms ║╔Execution stage started
+959ms ║║Calculating (string) Door to garage is open. Message + (string) 4 >> (string) Door to garage is open. Message 4
+964ms ║║Calculating (string) Door to garage is open. Message 4 + (string) of 20. >> (string) Door to garage is open. Message 4 of 20.
+1037ms ║║Executed virtual command sendPushNotification (67ms)
+1052ms ║║Comparison (enum) open is (string) open = true (3ms)
+1054ms ║║Condition #22 evaluated true (13ms)
+1062ms ║║Comparison (integer) 4 is_less_than (integer) 21 = true (3ms)
+1064ms ║║Condition #23 evaluated true (9ms)
+1066ms ║║Condition group #21 evaluated true (state did not change) (24ms)
+1074ms ║║Comparison (integer) 4 is_less_than_or_equal_to (integer) 19 = true (2ms)
+1077ms ║║Condition #25 evaluated true (7ms)
+1078ms ║║Condition group #24 evaluated true (state did not change) (10ms)
+1082ms ║║Cancelling statement #30’s schedules…
+1090ms ║║Calculating (integer) 4 + (integer) 1 >> (integer) 5
+1097ms ║║Executed virtual command setVariable (4ms)
+1105ms ║║Executed virtual command wait (1ms)
+1107ms ║║Requesting a wake up for Fri, Sep 7 2018 @ 9:58:58 AM MDT (in 60.0s)
+1115ms ║╚Execution stage complete. (190ms)
+1117ms ║Setting up scheduled job for Fri, Sep 7 2018 @ 9:58:58 AM MDT (in 59.992s)
+1135ms ╚Event processed successfully (1136ms)

9/7/2018, 9:56:57 AM +244ms
+1ms ╔Received event [Home].time = 1536335818168 with a delay of -924ms
+905ms ║RunTime Analysis CS > 131ms > PS > 733ms > PE > 40ms > CE
+909ms ║Runtime (44690 bytes) successfully initialized in 733ms (v0.3.108.20180906) (907ms)
+911ms ║╔Execution stage started
+947ms ║║Calculating (string) Door to garage is open. Message + (string) 3 >> (string) Door to garage is open. Message 3
+953ms ║║Calculating (string) Door to garage is open. Message 3 + (string) of 20. >> (string) Door to garage is open. Message 3 of 20.
+1017ms ║║Executed virtual command sendPushNotification (58ms)
+1033ms ║║Comparison (enum) open is (string) open = true (3ms)
+1035ms ║║Condition #22 evaluated true (14ms)
+1042ms ║║Comparison (integer) 3 is_less_than (integer) 21 = true (2ms)
+1044ms ║║Condition #23 evaluated true (8ms)
+1045ms ║║Condition group #21 evaluated true (state did not change) (25ms)
+1055ms ║║Comparison (integer) 3 is_less_than_or_equal_to (integer) 19 = true (2ms)
+1057ms ║║Condition #25 evaluated true (8ms)
+1058ms ║║Condition group #24 evaluated true (state did not change) (10ms)
+1062ms ║║Cancelling statement #30’s schedules…
+1070ms ║║Calculating (integer) 3 + (integer) 1 >> (integer) 4
+1078ms ║║Executed virtual command setVariable (5ms)
+1086ms ║║Executed virtual command wait (1ms)
+1088ms ║║Requesting a wake up for Fri, Sep 7 2018 @ 9:57:58 AM MDT (in 60.0s)
+1096ms ║╚Execution stage complete. (186ms)
+1099ms ║Setting up scheduled job for Fri, Sep 7 2018 @ 9:57:58 AM MDT (in 59.991s)
+1112ms ╚Event processed successfully (1112ms)
9/7/2018, 9:55:57 AM +606ms
+1ms ╔Received event [Home].time = 1536335757542 with a delay of 64ms
+353ms ║RunTime Analysis CS > 169ms > PS > 155ms > PE > 28ms > CE
+356ms ║Runtime (44688 bytes) successfully initialized in 155ms (v0.3.108.20180906) (353ms)
+358ms ║╔Execution stage started
+401ms ║║Calculating (string) Door to garage is open. Message + (string) 2 >> (string) Door to garage is open. Message 2
+407ms ║║Calculating (string) Door to garage is open. Message 2 + (string) of 20. >> (string) Door to garage is open. Message 2 of 20.
+479ms ║║Executed virtual command sendPushNotification (65ms)
+496ms ║║Comparison (enum) open is (string) open = true (4ms)
+499ms ║║Condition #22 evaluated true (15ms)
+506ms ║║Comparison (integer) 2 is_less_than (integer) 21 = true (2ms)
+509ms ║║Condition #23 evaluated true (8ms)
+510ms ║║Condition group #21 evaluated true (state did not change) (27ms)
+519ms ║║Comparison (integer) 2 is_less_than_or_equal_to (integer) 19 = true (2ms)
+521ms ║║Condition #25 evaluated true (7ms)
+523ms ║║Condition group #24 evaluated true (state did not change) (9ms)
+527ms ║║Cancelling statement #30’s schedules…
+536ms ║║Calculating (integer) 2 + (integer) 1 >> (integer) 3
+548ms ║║Executed virtual command setVariable (8ms)
+558ms ║║Executed virtual command wait (1ms)
+561ms ║║Requesting a wake up for Fri, Sep 7 2018 @ 9:56:58 AM MDT (in 60.0s)
+572ms ║╚Execution stage complete. (215ms)
+575ms ║Setting up scheduled job for Fri, Sep 7 2018 @ 9:56:58 AM MDT (in 59.988s)
+587ms ╚Event processed successfully (586ms)
9/7/2018, 9:54:57 AM +352ms
+1ms ╔Received event [Door to Garage].contact = open with a delay of 107ms
+87ms ║RunTime Analysis CS > 21ms > PS > 47ms > PE > 19ms > CE
+89ms ║Runtime (44696 bytes) successfully initialized in 47ms (v0.3.108.20180906) (87ms)
+90ms ║╔Execution stage started
+101ms ║║Comparison (enum) open changes_to (string) open = true (1ms)
+103ms ║║Cancelling condition #2’s schedules…
+104ms ║║Condition #2 evaluated true (8ms)
+105ms ║║Cancelling condition #1’s schedules…
+106ms ║║Condition group #1 evaluated true (state changed) (10ms)
+109ms ║║Cancelling statement #7’s schedules…
+116ms ║║Executed virtual command setVariable (3ms)
+131ms ║║Executed virtual command sendPushNotification (10ms)
+141ms ║║Comparison (enum) open is (string) open = true (2ms)
+143ms ║║Condition #22 evaluated true (7ms)
+148ms ║║Comparison (integer) 1 is_less_than (integer) 21 = true (2ms)
+150ms ║║Condition #23 evaluated true (6ms)
+152ms ║║Condition group #21 evaluated true (state did not change) (17ms)
+160ms ║║Comparison (integer) 1 is_less_than_or_equal_to (integer) 19 = true (2ms)
+162ms ║║Condition #25 evaluated true (7ms)
+163ms ║║Condition group #24 evaluated true (state did not change) (9ms)
+167ms ║║Cancelling statement #30’s schedules…
+174ms ║║Calculating (integer) 1 + (integer) 1 >> (integer) 2
+180ms ║║Executed virtual command setVariable (3ms)
+187ms ║║Executed virtual command wait (1ms)
+189ms ║║Requesting a wake up for Fri, Sep 7 2018 @ 9:55:57 AM MDT (in 60.0s)
+196ms ║╚Execution stage complete. (106ms)
+198ms ║Setting up scheduled job for Fri, Sep 7 2018 @ 9:55:57 AM MDT (in 59.993s)
+209ms ╚Event processed successfully (209ms)
9/7/2018, 9:54:56 AM +102ms
+1ms ╔Received event [Home].time = 1536335697770 with a delay of -1669ms
+223ms ║RunTime Analysis CS > 116ms > PS > 87ms > PE > 20ms > CE
+226ms ║Runtime (44696 bytes) successfully initialized in 87ms (v0.3.108.20180906) (224ms)
+227ms ║╔Execution stage started
+228ms ║╚Execution stage complete. (2ms)
+230ms ╚Event processed successfully (230ms)

Clear

Full Nothing selected None Minimal Medium Full

Logging level

Variables

Local variables

integertimesToWarn 7

integerintervalToWarn1

Global variables

boolean@firstTimeThroughtrue

boolean@holdMotionNotificationsfalse

boolean@sendSetpointChangeMessagetrue

boolean@sendSpeakNotificationstrue

dynamic@timeDogWasFedDayFriday

time@timeDogWasFedTime3:03:00 PM

boolean@turnPatioLightsOntrue

System variables

dynamic$argsnull

integer$day7

integer$dayOfWeek5

string$dayOfWeekNameFriday

device$deviceLocation

device$devicesLocation

integer$hour9

integer$hour249

string$httpContentType

integer$httpStatusCode

boolean$httpStatusOk

integer$iftttStatusCode

boolean$iftttStatusOk

dynamic$incidentsnull

decimal$index

dynamic$jsonnull

datetime$localNow1536313772031

device$locationLocation

string$locationModeHome

integer$mediaSize0

string$meridianAM

string$meridianWithDotsA.M.

datetime$midnight9/7/2018, 12:00:00 AM

integer$minute49

integer$month9

string$monthNameSeptember

string$nameSide Gate is Open

datetime$nextMidnight9/8/2018, 12:00:00 AM

datetime$nextNoon9/7/2018, 12:00:00 PM

datetime$nextScheduledTimeInvalid Date

datetime$nextSunrise9/8/2018, 6:33:00 AM

datetime$nextSunset9/7/2018, 7:21:00 PM

dynamic$nflnull

datetime$noon9/7/2018, 12:00:00 PM

datetime$now9/7/2018, 9:49:32 AM

dynamic$placesnull

[eibyer]

I believe there’s a scheduling issue with the ST platform right now so today is probably not a good day to figure this out.

Pistons with waits failing

The latest reply in the SmartThings community topic suggests that it is definitely a related issue, for anyone that did not see the earlier link we are also discussing this over here:

Edit: I did get to 6 count when I imported your piston, then it went overdue by about 45 seconds and then it went to recovery.

[eibyer]

It looks like schedules are working again. I made a few minor changes to your original and changed to Logging only so I don’t flood my users with notices