Issue with Piston Execution

[ViperTK]

1) Give a description of the problem
Switching the lights on is working fine, however, I wanted it to switch off the lights when there is no motion and the garage is closed.

However, even when there is motion in the garage, it still executes the switch off command when there is no motion for five minutes.

2) What is the expected behaviour?
On motion, the script should reset and go back to the 5 minute counter on next inactive motion event and the lights should stay on for another 5 minutes.

3) What is happening/not happening?
Please see answer in Q1.

4) Post a Green Snapshot of the piston

5) Attach logs after turning logging level to Full

12/8/2020, 10:08:16 AM +131ms
+1ms ╔Received event [King's Landing].time = 1607450897931 with a delay of -1800ms
+77ms ║RunTime Analysis CS > 21ms > PS > 6ms > PE > 50ms > CE
+80ms ║Runtime (41000 bytes) successfully initialized in 6ms (v0.3.110.20191009) (78ms)
+81ms ║╔Execution stage started
+91ms ║║Cancelling condition #12's schedules...
+91ms ║║Condition #12 evaluated true (1ms)
+101ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+102ms ║║Condition #13 evaluated true (10ms)
+103ms ║║Cancelling condition #2's schedules...
+104ms ║║Condition group #2 evaluated true (state changed) (14ms)
+106ms ║║Cancelling statement #7's schedules...
+1230ms ║║Executed physical command [Garage Lights].off() (1121ms)
+1231ms ║║Executed [Garage Lights].off (1123ms)
+1233ms ║╚Execution stage complete. (1152ms)
+1234ms ╚Event processed successfully (1234ms)
12/8/2020, 10:03:17 AM +817ms
+1ms ╔Received event [Garage Motion].motion = inactive with a delay of 202ms
+82ms ║RunTime Analysis CS > 18ms > PS > 6ms > PE > 59ms > CE
+84ms ║Runtime (40985 bytes) successfully initialized in 6ms (v0.3.110.20191009) (82ms)
+85ms ║╔Execution stage started
+98ms ║║Condition #3 evaluated false (9ms)
+102ms ║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+103ms ║║Cancelling condition #4's schedules...
+104ms ║║Condition #4 evaluated false (5ms)
+105ms ║║Cancelling condition #1's schedules...
+106ms ║║Condition group #1 evaluated false (state changed) (17ms)
+111ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+113ms ║║Adding a timed trigger schedule for condition 12
+116ms ║║Cancelling condition #12's schedules...
+117ms ║║Condition #12 evaluated false (9ms)
+118ms ║║Cancelling condition #2's schedules...
+118ms ║║Condition group #2 evaluated false (state changed) (11ms)
+126ms ║║Condition #16 evaluated false (7ms)
+127ms ║║Condition group #15 evaluated false (state did not change) (8ms)
+129ms ║╚Execution stage complete. (44ms)
+131ms ║Setting up scheduled job for Tue, Dec 8 2020 @ 10:08:17 AM PST (in 299.984s)
+137ms ╚Event processed successfully (138ms)
12/8/2020, 10:02:28 AM +70ms
+1ms ╔Received event [Garage Motion].motion = active with a delay of 168ms
+84ms ║RunTime Analysis CS > 15ms > PS > 4ms > PE > 65ms > CE
+86ms ║Runtime (40990 bytes) successfully initialized in 4ms (v0.3.110.20191009) (84ms)
+87ms ║╔Execution stage started
+97ms ║║Condition #3 evaluated false (5ms)
+100ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+102ms ║║Cancelling condition #4's schedules...
+102ms ║║Condition #4 evaluated true (5ms)
+103ms ║║Cancelling condition #1's schedules...
+104ms ║║Condition group #1 evaluated true (state changed) (13ms)
+106ms ║║Cancelling statement #9's schedules...
+727ms ║║Executed physical command [Garage Lights].on() (618ms)
+728ms ║║Executed [Garage Lights].on (620ms)
+731ms ║╚Execution stage complete. (644ms)
+732ms ╚Event processed successfully (732ms)
12/8/2020, 9:28:13 AM +143ms
+0ms ╔Received event [King's Landing].time = 1607448494168 with a delay of -1025ms
+78ms ║RunTime Analysis CS > 21ms > PS > 5ms > PE > 52ms > CE
+81ms ║Runtime (41000 bytes) successfully initialized in 5ms (v0.3.110.20191009) (79ms)
+81ms ║╔Execution stage started
+90ms ║║Cancelling condition #12's schedules...
+91ms ║║Condition #12 evaluated true (1ms)
+99ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+101ms ║║Condition #13 evaluated true (10ms)
+102ms ║║Cancelling condition #2's schedules...
+102ms ║║Condition group #2 evaluated true (state changed) (13ms)
+104ms ║║Cancelling statement #7's schedules...
+711ms ║║Executed physical command [Garage Lights].off() (603ms)
+712ms ║║Executed [Garage Lights].off (605ms)
+714ms ║╚Execution stage complete. (633ms)
+716ms ╚Event processed successfully (715ms)
12/8/2020, 9:23:14 AM +72ms
+1ms ╔Received event [Garage Motion].motion = inactive with a delay of 179ms
+68ms ║RunTime Analysis CS > 16ms > PS > 4ms > PE > 48ms > CE
+71ms ║Runtime (40985 bytes) successfully initialized in 4ms (v0.3.110.20191009) (69ms)
+71ms ║╔Execution stage started
+82ms ║║Condition #3 evaluated false (7ms)
+85ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+87ms ║║Cancelling condition #4's schedules...
+87ms ║║Condition #4 evaluated false (4ms)
+88ms ║║Cancelling condition #1's schedules...
+89ms ║║Condition group #1 evaluated false (state changed) (14ms)
+94ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+96ms ║║Adding a timed trigger schedule for condition 12
+98ms ║║Cancelling condition #12's schedules...
+98ms ║║Condition #12 evaluated false (8ms)
+99ms ║║Cancelling condition #2's schedules...
+100ms ║║Condition group #2 evaluated false (state changed) (10ms)
+106ms ║║Condition #16 evaluated false (4ms)
+106ms ║║Condition group #15 evaluated false (state did not change) (5ms)
+109ms ║╚Execution stage complete. (37ms)
+110ms ║Setting up scheduled job for Tue, Dec 8 2020 @ 9:28:14 AM PST (in 299.987s)
+117ms ╚Event processed successfully (116ms)
12/8/2020, 9:22:44 AM +191ms
+1ms ╔Received event [Garage Motion].motion = active with a delay of 163ms
+164ms ║RunTime Analysis CS > 21ms > PS > 6ms > PE > 137ms > CE
+166ms ║Runtime (40992 bytes) successfully initialized in 6ms (v0.3.110.20191009) (164ms)
+167ms ║╔Execution stage started
+179ms ║║Condition #3 evaluated false (7ms)
+183ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+185ms ║║Cancelling condition #4's schedules...
+186ms ║║Condition #4 evaluated true (5ms)
+187ms ║║Cancelling condition #1's schedules...
+188ms ║║Condition group #1 evaluated true (state changed) (16ms)
+190ms ║║Cancelling statement #9's schedules...
+306ms ║║Executed physical command [Garage Lights].on() (113ms)
+307ms ║║Executed [Garage Lights].on (115ms)
+309ms ║╚Execution stage complete. (142ms)
+311ms ╚Event processed successfully (310ms)
12/7/2020, 8:27:18 PM +438ms
+1ms ╔Received event [King's Landing].time = 1607401638781 with a delay of -343ms
+101ms ║RunTime Analysis CS > 21ms > PS > 7ms > PE > 73ms > CE
+104ms ║Runtime (41002 bytes) successfully initialized in 7ms (v0.3.110.20191009) (102ms)
+105ms ║╔Execution stage started
+121ms ║║Cancelling condition #12's schedules...
+122ms ║║Condition #12 evaluated true (2ms)
+134ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+136ms ║║Condition #13 evaluated true (13ms)
+138ms ║║Cancelling condition #2's schedules...
+139ms ║║Condition group #2 evaluated true (state changed) (19ms)
+142ms ║║Cancelling statement #7's schedules...
+151ms ║║Skipped execution of physical command [Garage Lights].off([]) because it would make no change to the device. (4ms)
+152ms ║║Executed [Garage Lights].off (6ms)
+155ms ║╚Execution stage complete. (50ms)
+156ms ╚Event processed successfully (156ms)
12/7/2020, 8:22:57 PM +151ms
+1ms ╔Received event [Garage Motion].motion = inactive with a delay of 387ms
+75ms ║RunTime Analysis CS > 20ms > PS > 5ms > PE > 50ms > CE
+78ms ║Runtime (40989 bytes) successfully initialized in 5ms (v0.3.110.20191009) (76ms)
+79ms ║╔Execution stage started
+91ms ║║Condition #3 evaluated false (7ms)
+94ms ║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+96ms ║║Cancelling condition #4's schedules...
+96ms ║║Condition #4 evaluated false (5ms)
+97ms ║║Cancelling condition #1's schedules...
+98ms ║║Condition group #1 evaluated false (state changed) (16ms)
+103ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+105ms ║║Condition #12 evaluated false (6ms)
+106ms ║║Condition group #2 evaluated false (state did not change) (7ms)
+114ms ║║Condition #16 evaluated false (6ms)
+115ms ║║Condition group #15 evaluated false (state did not change) (7ms)
+117ms ║╚Execution stage complete. (39ms)
+118ms ║Setting up scheduled job for Mon, Dec 7 2020 @ 8:27:18 PM PST (in 261.512s)
+129ms ╚Event processed successfully (128ms)
12/7/2020, 8:22:22 PM +570ms
+1ms ╔Received event [Garage Motion].motion = active with a delay of 136ms
+293ms ║RunTime Analysis CS > 237ms > PS > 5ms > PE > 50ms > CE
+295ms ║Runtime (40996 bytes) successfully initialized in 5ms (v0.3.110.20191009) (293ms)
+296ms ║╔Execution stage started
+309ms ║║Condition #3 evaluated false (8ms)
+312ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+313ms ║║Cancelling condition #4's schedules...
+314ms ║║Condition #4 evaluated true (5ms)
+315ms ║║Cancelling condition #1's schedules...
+316ms ║║Condition group #1 evaluated true (state changed) (17ms)
+318ms ║║Cancelling statement #9's schedules...
+325ms ║║Skipped execution of physical command [Garage Lights].on([]) because it would make no change to the device. (4ms)
+326ms ║║Executed [Garage Lights].on (6ms)
+329ms ║╚Execution stage complete. (34ms)
+330ms ║Setting up scheduled job for Mon, Dec 7 2020 @ 8:27:18 PM PST (in 295.881s)
+342ms ╚Event processed successfully (342ms)
12/7/2020, 8:22:18 PM +685ms
+0ms ╔Received event [Garage Motion].motion = inactive with a delay of 176ms
+66ms ║RunTime Analysis CS > 16ms > PS > 4ms > PE > 47ms > CE
+69ms ║Runtime (40987 bytes) successfully initialized in 4ms (v0.3.110.20191009) (68ms)
+70ms ║╔Execution stage started
+80ms ║║Condition #3 evaluated false (6ms)
+84ms ║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+86ms ║║Cancelling condition #4's schedules...
+87ms ║║Condition #4 evaluated false (5ms)
+88ms ║║Cancelling condition #1's schedules...
+88ms ║║Condition group #1 evaluated false (state changed) (14ms)
+94ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+96ms ║║Adding a timed trigger schedule for condition 12
+98ms ║║Cancelling condition #12's schedules...
+99ms ║║Condition #12 evaluated false (9ms)
+100ms ║║Cancelling condition #2's schedules...
+101ms ║║Condition group #2 evaluated false (state changed) (12ms)
+108ms ║║Condition #16 evaluated false (6ms)
+110ms ║║Condition group #15 evaluated false (state did not change) (7ms)
+112ms ║╚Execution stage complete. (42ms)
+113ms ║Setting up scheduled job for Mon, Dec 7 2020 @ 8:27:18 PM PST (in 299.983s)
+121ms ╚Event processed successfully (121ms)
12/7/2020, 8:21:48 PM +904ms
+2ms ╔Received event [Garage Motion].motion = active with a delay of 199ms
+75ms ║RunTime Analysis CS > 19ms > PS > 6ms > PE > 50ms > CE
+78ms ║Runtime (40992 bytes) successfully initialized in 6ms (v0.3.110.20191009) (75ms)
+79ms ║╔Execution stage started
+91ms ║║Condition #3 evaluated false (8ms)
+95ms ║║Comparison (enum) active changes_to (string) active = true (0ms)
+96ms ║║Cancelling condition #4's schedules...
+97ms ║║Condition #4 evaluated true (5ms)
+98ms ║║Cancelling condition #1's schedules...
+99ms ║║Condition group #1 evaluated true (state changed) (16ms)
+101ms ║║Cancelling statement #9's schedules...
+684ms ║║Executed physical command [Garage Lights].on() (578ms)
+685ms ║║Executed [Garage Lights].on (580ms)
+687ms ║╚Execution stage complete. (609ms)
+688ms ╚Event processed successfully (688ms)
12/7/2020, 8:01:43 PM +146ms
+0ms ╔Received event [King's Landing].time = 1607400104720 with a delay of -1575ms
+203ms ║RunTime Analysis CS > 144ms > PS > 7ms > PE > 53ms > CE
+206ms ║Runtime (41004 bytes) successfully initialized in 7ms (v0.3.110.20191009) (204ms)
+206ms ║╔Execution stage started
+216ms ║║Cancelling condition #12's schedules...
+216ms ║║Condition #12 evaluated true (1ms)
+226ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+227ms ║║Condition #13 evaluated true (10ms)
+228ms ║║Cancelling condition #2's schedules...
+229ms ║║Condition group #2 evaluated true (state changed) (14ms)
+231ms ║║Cancelling statement #7's schedules...
+239ms ║║Skipped execution of physical command [Garage Lights].off([]) because it would make no change to the device. (4ms)
+239ms ║║Executed [Garage Lights].off (6ms)
+242ms ║╚Execution stage complete. (35ms)
+243ms ╚Event processed successfully (242ms)
12/7/2020, 7:56:44 PM +622ms
+0ms ╔Received event [Garage Motion].motion = inactive with a delay of 185ms
+70ms ║RunTime Analysis CS > 15ms > PS > 4ms > PE > 52ms > CE
+73ms ║Runtime (40987 bytes) successfully initialized in 4ms (v0.3.110.20191009) (71ms)
+74ms ║╔Execution stage started
+83ms ║║Condition #3 evaluated false (6ms)
+86ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+88ms ║║Cancelling condition #4's schedules...
+88ms ║║Condition #4 evaluated false (4ms)
+89ms ║║Cancelling condition #1's schedules...
+90ms ║║Condition group #1 evaluated false (state changed) (13ms)
+95ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+97ms ║║Adding a timed trigger schedule for condition 12
+99ms ║║Cancelling condition #12's schedules...
+100ms ║║Condition #12 evaluated false (9ms)
+101ms ║║Cancelling condition #2's schedules...
+102ms ║║Condition group #2 evaluated false (state changed) (11ms)
+109ms ║║Condition #16 evaluated false (6ms)
+110ms ║║Condition group #15 evaluated false (state did not change) (7ms)
+113ms ║╚Execution stage complete. (39ms)
+114ms ║Setting up scheduled job for Mon, Dec 7 2020 @ 8:01:44 PM PST (in 299.985s)
+120ms ╚Event processed successfully (120ms)
12/7/2020, 7:56:15 PM +365ms
+1ms ╔Received event [Garage Motion].motion = active with a delay of 158ms
+72ms ║RunTime Analysis CS > 17ms > PS > 5ms > PE > 51ms > CE
+74ms ║Runtime (40992 bytes) successfully initialized in 5ms (v0.3.110.20191009) (72ms)
+75ms ║╔Execution stage started
+87ms ║║Condition #3 evaluated false (7ms)
+90ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+91ms ║║Cancelling condition #4's schedules...
+92ms ║║Condition #4 evaluated true (5ms)
+93ms ║║Cancelling condition #1's schedules...
+94ms ║║Condition group #1 evaluated true (state changed) (15ms)
+96ms ║║Cancelling statement #9's schedules...
+3695ms ║║Executed physical command [Garage Lights].on() (3596ms)
+3696ms ║║Executed [Garage Lights].on (3598ms)
+3698ms ║╚Execution stage complete. (3623ms)
+3699ms ╚Event processed successfully (3699ms)
12/7/2020, 7:56:03 PM +78ms
+0ms ╔Received event [King's Landing].time = 1607399764712 with a delay of -1634ms
+85ms ║RunTime Analysis CS > 22ms > PS > 7ms > PE > 55ms > CE
+87ms ║Runtime (41002 bytes) successfully initialized in 7ms (v0.3.110.20191009) (86ms)
+88ms ║╔Execution stage started
+97ms ║║Cancelling condition #12's schedules...
+98ms ║║Condition #12 evaluated true (1ms)
+107ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+109ms ║║Condition #13 evaluated true (10ms)
+110ms ║║Cancelling condition #2's schedules...
+110ms ║║Condition group #2 evaluated true (state changed) (14ms)
+113ms ║║Cancelling statement #7's schedules...
+748ms ║║Executed physical command [Garage Lights].off() (632ms)
+749ms ║║Executed [Garage Lights].off (634ms)
+751ms ║╚Execution stage complete. (663ms)
+752ms ╚Event processed successfully (752ms)
12/7/2020, 7:51:04 PM +614ms
+1ms ╔Received event [Garage Motion].motion = inactive with a delay of 186ms
+67ms ║RunTime Analysis CS > 16ms > PS > 4ms > PE > 47ms > CE
+70ms ║Runtime (40987 bytes) successfully initialized in 4ms (v0.3.110.20191009) (68ms)
+71ms ║╔Execution stage started
+82ms ║║Condition #3 evaluated false (6ms)
+86ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+87ms ║║Cancelling condition #4's schedules...
+88ms ║║Condition #4 evaluated false (6ms)
+89ms ║║Cancelling condition #1's schedules...
+90ms ║║Condition group #1 evaluated false (state changed) (15ms)
+96ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+98ms ║║Adding a timed trigger schedule for condition 12
+100ms ║║Cancelling condition #12's schedules...
+101ms ║║Condition #12 evaluated false (10ms)
+102ms ║║Cancelling condition #2's schedules...
+103ms ║║Condition group #2 evaluated false (state changed) (12ms)
+111ms ║║Condition #16 evaluated false (7ms)
+112ms ║║Condition group #15 evaluated false (state did not change) (8ms)
+115ms ║╚Execution stage complete. (45ms)
+116ms ║Setting up scheduled job for Mon, Dec 7 2020 @ 7:56:04 PM PST (in 299.983s)
+122ms ╚Event processed successfully (122ms)
12/7/2020, 7:50:29 PM +316ms
+1ms ╔Received event [Garage Motion].motion = active with a delay of 193ms
+64ms ║RunTime Analysis CS > 16ms > PS > 4ms > PE > 44ms > CE
+66ms ║Runtime (40992 bytes) successfully initialized in 4ms (v0.3.110.20191009) (64ms)
+67ms ║╔Execution stage started
+86ms ║║Condition #3 evaluated false (14ms)
+89ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+91ms ║║Cancelling condition #4's schedules...
+91ms ║║Condition #4 evaluated true (5ms)
+92ms ║║Cancelling condition #1's schedules...
+93ms ║║Condition group #1 evaluated true (state changed) (22ms)
+95ms ║║Cancelling statement #9's schedules...
+659ms ║║Executed physical command [Garage Lights].on() (561ms)
+660ms ║║Executed [Garage Lights].on (563ms)
+662ms ║╚Execution stage complete. (595ms)
+664ms ╚Event processed successfully (663ms)

[eibyer]

First suggestion, make the Else If’s into its separate If statement.

[WCmore]

In addition to @eibyer’s tip…

Lines 38 and 40 are both triggers, so will likely not be true at the same instant.

[ViperTK]

Thanks @eibyer, this definitely helped.
I didn’t even realize that those IFs are nested instead of being their separate conditions.