Piston using a 5 second wait is looping?


#1

I was trying to help someone else with location mode changes and threw a sample piston together. In the process I found an unexpected loop condition?

Here is the piston I was trying:

For some reason the wait section starts loping and reruns every 25+ seconds? It also never recognizes the change in location mode from home to test.

Here are the logs:

|9/7/2018, 3:41:07 AM +881ms|
|+0ms|╔Received event [Home].execute = recovery with a delay of 122ms|
|+117ms|║RunTime Analysis CS > 30ms > PS > 61ms > PE > 26ms > CE|
|+119ms|║Runtime (41830 bytes) successfully initialized in 61ms (v0.3.108.20180906) (118ms)|
|+121ms|║╔Execution stage started|
|+127ms|║║Cancelling statement #1’s schedules…|
|+155ms|║║Executed virtual command setLocationMode (25ms)|
|+163ms|║║Comparison (string) :ca74bc6d2a57b658492ce9d87c1e8684: is (string) :ca74bc6d2a57b658492ce9d87c1e8684: = true (2ms)|
|+165ms|║║Cancelling condition #4’s schedules…|
|+166ms|║║Condition #4 evaluated true (7ms)|
|+167ms|║║Cancelling condition #3’s schedules…|
|+169ms|║║Condition group #3 evaluated true (state changed) (10ms)|
|+171ms|║║Cancelling statement #5’s schedules…|
|+176ms|║║Executed virtual command wait (0ms)|
|+177ms|║║Requesting a wake up for Fri, Sep 7 2018 @ 3:41:13 AM CDT (in 5.0s)|
|+183ms|║╚Execution stage complete. (63ms)|
|+185ms|║Setting up scheduled job for Fri, Sep 7 2018 @ 3:41:13 AM CDT (in 4.994s)|
|+201ms|╚Event processed successfully (201ms)|
|9/7/2018, 3:41:07 AM +872ms|
|+0ms|╔Received event [Home].mode = Home with a delay of 95ms|
|+103ms|║RunTime Analysis CS > 28ms > PS > 50ms > PE > 25ms > CE|
|+105ms|║Runtime (41822 bytes) successfully initialized in 50ms (v0.3.108.20180906) (104ms)|
|+106ms|║╔Execution stage started|
|+112ms|║║Cancelling statement #1’s schedules…|
|+134ms|║║Executed virtual command setLocationMode (18ms)|
|+142ms|║║Comparison (string) :ca74bc6d2a57b658492ce9d87c1e8684: is (string) :ca74bc6d2a57b658492ce9d87c1e8684: = true (2ms)|
|+144ms|║║Cancelling condition #4’s schedules…|
|+146ms|║║Condition #4 evaluated true (8ms)|
|+147ms|║║Cancelling condition #3’s schedules…|
|+148ms|║║Condition group #3 evaluated true (state changed) (11ms)|
|+151ms|║║Cancelling statement #5’s schedules…|
|+156ms|║║Executed virtual command wait (1ms)|
|+158ms|║║Requesting a wake up for Fri, Sep 7 2018 @ 3:41:13 AM CDT (in 5.0s)|
|+163ms|║╚Execution stage complete. (57ms)|
|+165ms|║Setting up scheduled job for Fri, Sep 7 2018 @ 3:41:13 AM CDT (in 4.995s)|
|+177ms|╚Event processed successfully (177ms)|
|9/7/2018, 3:41:07 AM +624ms|
|+1ms|╔Received event [Home].mode = Test with a delay of 89ms|
|+109ms|║RunTime Analysis CS > 28ms > PS > 59ms > PE > 21ms > CE|
|+111ms|║Runtime (41820 bytes) successfully initialized in 59ms (v0.3.108.20180906) (110ms)|
|+113ms|║╔Execution stage started|
|+119ms|║║Cancelling statement #1’s schedules…|
|+164ms|║║Executed virtual command setLocationMode (42ms)|
|+172ms|║║Comparison (string) :98b88b0ac53cf63986ce6c6d405dade0: is (string) :ca74bc6d2a57b658492ce9d87c1e8684: = false (2ms)|
|+174ms|║║Cancelling condition #4’s schedules…|
|+175ms|║║Condition #4 evaluated false (8ms)|
|+177ms|║║Cancelling condition #3’s schedules…|
|+178ms|║║Condition group #3 evaluated false (state changed) (10ms)|
|+181ms|║╚Execution stage complete. (68ms)|
|+182ms|╚Event processed successfully (182ms)|
|9/7/2018, 3:41:06 AM +803ms|
|+1ms|╔Received event [Home].time = 1536309623484 with a delay of 43319ms|
|+563ms|║RunTime Analysis CS > 213ms > PS > 309ms > PE > 40ms > CE|
|+567ms|║Runtime (41835 bytes) successfully initialized in 309ms (v0.3.108.20180906) (565ms)|
|+569ms|║╔Execution stage started|
|+748ms|║║Executed virtual command setLocationMode (153ms)|
|+759ms|║║Calculating (string) we are in + (string) Home >> (string) we are in Home|
|+765ms|║║ we are in Home|
|+766ms|║║Executed virtual command log (1ms)|
|+769ms|║╚Execution stage complete. (201ms)|
|+770ms|╚Event processed successfully (770ms)|
|9/7/2018, 3:40:08 AM +330ms|
|+1ms|╔Received event [Home].mode = Home with a delay of 79ms|
|+10099ms|║RunTime Analysis CS > 14ms > PS > 10063ms > PE > 21ms > CE|
|+10100ms|║Piston waited at a semaphore for 10021ms|
|+10102ms|║Runtime (41902 bytes) successfully initialized in 10063ms (v0.3.108.20180906) (10100ms)|
|+10103ms|║╔Execution stage started|
|+10109ms|║║Cancelling statement #1’s schedules…|
|+10129ms|║║Executed virtual command setLocationMode (15ms)|
|+10137ms|║║Comparison (string) :ca74bc6d2a57b658492ce9d87c1e8684: is (string) :ca74bc6d2a57b658492ce9d87c1e8684: = true (3ms)|
|+10139ms|║║Cancelling condition #4’s schedules…|
|+10140ms|║║Condition #4 evaluated true (8ms)|
|+10142ms|║║Cancelling condition #3’s schedules…|
|+10143ms|║║Condition group #3 evaluated true (state changed) (11ms)|
|+10146ms|║║Cancelling statement #5’s schedules…|
|+10151ms|║║Executed virtual command wait (0ms)|
|+10153ms|║║Requesting a wake up for Fri, Sep 7 2018 @ 3:40:23 AM CDT (in 5.0s)|
|+10159ms|║╚Execution stage complete. (55ms)|
|+10161ms|║Setting up scheduled job for Fri, Sep 7 2018 @ 3:40:23 AM CDT (in 4.994s)|
|+10274ms|╚Event processed successfully (10274ms)|
|9/7/2018, 3:40:08 AM +127ms|
|+1ms|╔Received event [Home].mode = Test with a delay of 82ms|
|+88ms|║RunTime Analysis CS > 24ms > PS > 39ms > PE > 25ms > CE|
|+91ms|║Runtime (41816 bytes) successfully initialized in 39ms (v0.3.108.20180906) (89ms)|
|+92ms|║╔Execution stage started|
|+99ms|║║Cancelling statement #1’s schedules…|
|+137ms|║║Executed virtual command setLocationMode (33ms)|
|+146ms|║║Comparison (string) :98b88b0ac53cf63986ce6c6d405dade0: is (string) :ca74bc6d2a57b658492ce9d87c1e8684: = false (3ms)|
|+148ms|║║Cancelling condition #4’s schedules…|
|+149ms|║║Condition #4 evaluated false (8ms)|
|+151ms|║║Cancelling condition #3’s schedules…|
|+153ms|║║Condition group #3 evaluated false (state changed) (12ms)|
|+155ms|║╚Execution stage complete. (63ms)|
|+157ms|╚Event processed successfully (157ms)|
|9/7/2018, 3:40:07 AM +558ms|
|+0ms|╔Received event [Home].time = 1536309590835 with a delay of 16722ms|
|+376ms|║RunTime Analysis CS > 126ms > PS > 217ms > PE > 34ms > CE|
|+380ms|║Runtime (41832 bytes) successfully initialized in 217ms (v0.3.108.20180906) (379ms)|
|+382ms|║╔Execution stage started|
|+502ms|║║Executed virtual command setLocationMode (96ms)|
|+515ms|║║Calculating (string) we are in + (string) Home >> (string) we are in Home|
|+521ms|║║ we are in Home|
|+523ms|║║Executed virtual command log (3ms)|
|+528ms|║╚Execution stage complete. (147ms)|
|+530ms|╚Event processed successfully (530ms)|
|9/7/2018, 3:39:45 AM +680ms|
|+0ms|╔Received event [Home].mode = Home with a delay of 94ms|
|+101ms|║RunTime Analysis CS > 26ms > PS > 52ms > PE > 24ms > CE|
|+104ms|║Runtime (41822 bytes) successfully initialized in 52ms (v0.3.108.20180906) (103ms)|
|+105ms|║╔Execution stage started|
|+111ms|║║Cancelling statement #1’s schedules…|
|+131ms|║║Executed virtual command setLocationMode (17ms)|
|+140ms|║║Comparison (string) :ca74bc6d2a57b658492ce9d87c1e8684: is (string) :ca74bc6d2a57b658492ce9d87c1e8684: = true (1ms)|
|+142ms|║║Cancelling condition #4’s schedules…|
|+143ms|║║Condition #4 evaluated true (8ms)|
|+144ms|║║Cancelling condition #3’s schedules…|
|+145ms|║║Condition group #3 evaluated true (state changed) (11ms)|
|+148ms|║║Cancelling statement #5’s schedules…|
|+153ms|║║Executed virtual command wait (0ms)|
|+154ms|║║Requesting a wake up for Fri, Sep 7 2018 @ 3:39:50 AM CDT (in 5.0s)|
|+160ms|║╚Execution stage complete. (55ms)|
|+162ms|║Setting up scheduled job for Fri, Sep 7 2018 @ 3:39:50 AM CDT (in 4.994s)|
|+175ms|╚Event processed successfully (175ms)|
|9/7/2018, 3:39:44 AM +737ms|
|+1ms|╔Received event [Home].time = 1536309568896 with a delay of 15841ms|
|+435ms|║RunTime Analysis CS > 202ms > PS > 208ms > PE > 24ms > CE|
|+437ms|║Runtime (41832 bytes) successfully initialized in 208ms (v0.3.108.20180906) (435ms)|
|+439ms|║╔Execution stage started|
|+666ms|║║Executed virtual command setLocationMode (210ms)|
|+676ms|║║Calculating (string) we are in + (string) Home >> (string) we are in Home|
|+682ms|║║ we are in Home|
|+683ms|║║Executed virtual command log (2ms)|
|+686ms|║╚Execution stage complete. (248ms)|
|+688ms|╚Event processed successfully (687ms)|


#2

The logs confirm that it does set the mode to Test (Received event [Home].mode = Test). Your trigger Location mode is Home subscribes to any changes in the mode, so as soon as it changes to Test the piston runs immediately because of that trigger and the first statement in the piston sets the mode back to Home.


#3

Interesting. I would have thought that the if statement would have fired but not the whole piston.

Thank you


#4

Please also see the following which is related specifically to the wait, you may want to chime in there and also on the SmartThings community topic.