Why does this only work SOMETIMES. Completely flakey

fredfon · 2021-05-07 01:10:55 UTC

1) Give a description of the problem
Only works occasionally. Completely unreliable.
2) What is the expected behaviour?
With motion on either a cam or a motion sensor a virtual switch gets turned “on”.
When that switch changes to on a lightswitch gets turned on and a timer starts and light switch turns off after set time.
There is also a timer to turn the virtual switch back off.
The goal is to have each motion event restart the timer to avoid the light constantly turning off and on with motion.
3) What is happening/not happening?
It just sometimes doesn’t work. Oftentimes the virtual switch never gets set back to “off”. (I’ve tried various times from 0 seconds up to ten seconds)
**4) Post a Green Snapshot of the piston![image|45x37]

5) Attach logs after turning logging level to Full

5/6/2021, 9:09:02 PM +181ms
+0ms ╔Received event [Charles St].time = 1620349742741 with a delay of -561ms
+88ms ║RunTime Analysis CS &gt; 21ms &gt; PS &gt; 8ms &gt; PE &gt; 59ms &gt; CE
+91ms ║Runtime (40237 bytes) successfully initialized in 8ms (v0.3.110.20191009) (90ms)
+93ms ║╔Execution stage started
+145ms ║║Executed physical command [Front Foyer Chandelier].off() (30ms)
+146ms ║║Executed [Front Foyer Chandelier].off (32ms)
+148ms ║╚Execution stage complete. (56ms)
+149ms ╚Event processed successfully (150ms)
5/6/2021, 9:07:12 PM +188ms
+0ms ╔Received event [foyer virtual switch].switch = off with a delay of 78ms
+71ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 6ms &gt; PE &gt; 49ms &gt; CE
+73ms ║Runtime (40236 bytes) successfully initialized in 6ms (v0.3.110.20191009) (72ms)
+74ms ║╔Execution stage started
+86ms ║║Condition #3 evaluated false (6ms)
+93ms ║║Condition #5 evaluated false (6ms)
+94ms ║║Condition group #2 evaluated false (state did not change) (15ms)
+95ms ║║Condition group #1 evaluated false (state did not change) (16ms)
+101ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+102ms ║║Condition #13 evaluated false (4ms)
+103ms ║║Condition group #12 evaluated false (state did not change) (5ms)
+106ms ║╚Execution stage complete. (32ms)
+107ms ║Setting up scheduled job for Thu, May 6 2021 @ 9:09:02 PM EDT (in 110.446s)
+117ms ╚Event processed successfully (117ms)
5/6/2021, 9:07:11 PM +171ms
+0ms ╔Received event [Charles St].time = 1620349632183 with a delay of -1012ms
+99ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 8ms &gt; PE &gt; 67ms &gt; CE
+101ms ║Runtime (40232 bytes) successfully initialized in 8ms (v0.3.110.20191009) (100ms)
+102ms ║╔Execution stage started
+129ms ║║Executed physical command [null].off() (10ms)
+130ms ║║Executed [foyer virtual switch].off (13ms)
+141ms ║║Cancelling condition #13's schedules...
+142ms ║║Condition #13 evaluated false (8ms)
+144ms ║║Cancelling condition #12's schedules...
+145ms ║║Condition group #12 evaluated false (state changed) (11ms)
+148ms ║╚Execution stage complete. (46ms)
+150ms ║Setting up scheduled job for Thu, May 6 2021 @ 9:09:02 PM EDT (in 111.421s)
+157ms ╚Event processed successfully (156ms)
5/6/2021, 9:07:02 PM +566ms
+2ms ╔Received event [foyer virtual switch].switch = on with a delay of 154ms
+97ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 11ms &gt; PE &gt; 62ms &gt; CE
+100ms ║Runtime (40233 bytes) successfully initialized in 11ms (v0.3.110.20191009) (97ms)
+100ms ║╔Execution stage started
+111ms ║║Condition #3 evaluated false (6ms)
+119ms ║║Cancelling condition #5's schedules...
+120ms ║║Condition #5 evaluated false (7ms)
+121ms ║║Cancelling condition #2's schedules...
+122ms ║║Condition group #2 evaluated false (state changed) (16ms)
+123ms ║║Cancelling condition #1's schedules...
+123ms ║║Condition group #1 evaluated false (state changed) (19ms)
+129ms ║║Comparison (enum) on changes_to (string) on = true (0ms)
+130ms ║║Cancelling condition #13's schedules...
+131ms ║║Condition #13 evaluated true (4ms)
+132ms ║║Cancelling condition #12's schedules...
+132ms ║║Condition group #12 evaluated true (state changed) (7ms)
+134ms ║║Cancelling statement #14's schedules...
+169ms ║║Executed physical command [Front Foyer Chandelier].setLevel([78]) (31ms)
+170ms ║║Executed [Front Foyer Chandelier].setLevel (33ms)
+173ms ║║Executed virtual command [Front Foyer Chandelier].wait (1ms)
+174ms ║║Requesting a wake up for Thu, May 6 2021 @ 9:09:02 PM EDT (in 120.0s)
+178ms ║╚Execution stage complete. (78ms)
+180ms ║Setting up scheduled job for Thu, May 6 2021 @ 9:07:12 PM EDT (in 9.438s), with 1 more job pending
+192ms ╚Event processed successfully (192ms)
5/6/2021, 9:07:01 PM +997ms
+1ms ╔Received event [Aa Foyer Motion Sensor].motion = active with a delay of 193ms
+83ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 6ms &gt; PE &gt; 55ms &gt; CE
+86ms ║Runtime (40245 bytes) successfully initialized in 6ms (v0.3.110.20191009) (84ms)
+87ms ║╔Execution stage started
+100ms ║║Condition #3 evaluated false (7ms)
+104ms ║║Comparison (enum) active changes_to (string) active = true (0ms)
+105ms ║║Cancelling condition #5's schedules...
+106ms ║║Condition #5 evaluated true (6ms)
+107ms ║║Cancelling condition #2's schedules...
+108ms ║║Condition group #2 evaluated true (state changed) (16ms)
+150ms ║║Comparison (time) 76022106 is_between (time) 1620345060000 .. (time) 1620293820000 = true (9ms)
+151ms ║║Time restriction check passed
+153ms ║║Condition #18 evaluated true (44ms)
+161ms ║║Comparison (enum) off is (string) off = true (1ms)
+162ms ║║Condition #21 evaluated true (8ms)
+163ms ║║Cancelling condition #1's schedules...
+164ms ║║Condition group #1 evaluated true (state changed) (73ms)
+166ms ║║Cancelling statement #8's schedules...
+180ms ║║Executed physical command [null].on() (11ms)
+181ms ║║Executed [foyer virtual switch].on (13ms)
+184ms ║║Executed virtual command [foyer virtual switch].wait (0ms)
+186ms ║║Requesting a wake up for Thu, May 6 2021 @ 9:07:12 PM EDT (in 10.0s)
+190ms ║╚Execution stage complete. (103ms)
+191ms ║Setting up scheduled job for Thu, May 6 2021 @ 9:07:12 PM EDT (in 9.995s)
+199ms ╚Event processed successfully (199ms)
5/6/2021, 9:01:55 PM +142ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 127ms
+83ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 7ms &gt; PE &gt; 54ms &gt; CE
+85ms ║Runtime (40236 bytes) successfully initialized in 7ms (v0.3.110.20191009) (84ms)
+86ms ║╔Execution stage started
+97ms ║║Condition #3 evaluated false (6ms)
+104ms ║║Condition #5 evaluated false (6ms)
+105ms ║║Condition group #2 evaluated false (state did not change) (15ms)
+106ms ║║Condition group #1 evaluated false (state did not change) (16ms)
+115ms ║║Condition #13 evaluated false (6ms)
+116ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+118ms ║╚Execution stage complete. (32ms)
+119ms ╚Event processed successfully (119ms)
5/6/2021, 9:01:18 PM +75ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 57ms
+10140ms ║RunTime Analysis CS &gt; 15ms &gt; PS &gt; 10060ms &gt; PE &gt; 65ms &gt; CE
+10141ms ║Piston waited at a semaphore for 10056ms
+10143ms ║Runtime (40318 bytes) successfully initialized in 10060ms (v0.3.110.20191009) (10141ms)
+10144ms ║╔Execution stage started
+10156ms ║║Condition #3 evaluated false (6ms)
+10163ms ║║Condition #5 evaluated false (7ms)
+10164ms ║║Condition group #2 evaluated false (state did not change) (15ms)
+10165ms ║║Condition group #1 evaluated false (state did not change) (17ms)
+10174ms ║║Condition #13 evaluated false (7ms)
+10175ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+10177ms ║╚Execution stage complete. (33ms)
+10178ms ╚Event processed successfully (10178ms)
5/6/2021, 9:01:17 PM +941ms
+0ms ╔Received event [Charles St].execute = recovery with a delay of 134ms
+10131ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 10054ms &gt; PE &gt; 55ms &gt; CE
+10132ms ║Piston waited at a semaphore for 10048ms
+10135ms ║Runtime (40319 bytes) successfully initialized in 10054ms (v0.3.110.20191009) (10133ms)
+10136ms ║╔Execution stage started
+10149ms ║║Condition #3 evaluated false (9ms)
+10158ms ║║Condition #5 evaluated false (8ms)
+10159ms ║║Condition group #2 evaluated false (state did not change) (19ms)
+10160ms ║║Condition group #1 evaluated false (state did not change) (21ms)
+10170ms ║║Condition #13 evaluated false (6ms)
+10171ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+10172ms ║╚Execution stage complete. (37ms)
+10173ms ╚Event processed successfully (10173ms)
5/6/2021, 9:01:17 PM +952ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 56ms
+10088ms ║RunTime Analysis CS &gt; 19ms &gt; PS &gt; 10020ms &gt; PE &gt; 48ms &gt; CE
+10088ms ║Piston waited at a semaphore for 10015ms
+10091ms ║Runtime (40318 bytes) successfully initialized in 10020ms (v0.3.110.20191009) (10089ms)
+10092ms ║╔Execution stage started
+10102ms ║║Condition #3 evaluated false (6ms)
+10109ms ║║Condition #5 evaluated false (5ms)
+10110ms ║║Condition group #2 evaluated false (state did not change) (13ms)
+10111ms ║║Condition group #1 evaluated false (state did not change) (15ms)
+10119ms ║║Condition #13 evaluated false (6ms)
+10120ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+10122ms ║╚Execution stage complete. (31ms)
+10123ms ╚Event processed successfully (10123ms)
5/6/2021, 9:01:17 PM +941ms
+0ms ╔Received event [Charles St].execute = recovery with a delay of 57ms
+84ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 6ms &gt; PE &gt; 60ms &gt; CE
+87ms ║Runtime (40235 bytes) successfully initialized in 6ms (v0.3.110.20191009) (86ms)
+88ms ║╔Execution stage started
+100ms ║║Condition #3 evaluated false (7ms)
+107ms ║║Condition #5 evaluated false (6ms)
+109ms ║║Condition group #2 evaluated false (state did not change) (16ms)
+109ms ║║Condition group #1 evaluated false (state did not change) (17ms)
+119ms ║║Condition #13 evaluated false (7ms)
+120ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+169ms ║║Executed physical command [Front Foyer Chandelier].off() (31ms)
+169ms ║║Executed [Front Foyer Chandelier].off (32ms)
+172ms ║╚Execution stage complete. (84ms)
+173ms ╚Event processed successfully (173ms)
5/6/2021, 8:58:37 PM +876ms
+1ms ╔Received event [foyer virtual switch].switch = off with a delay of 144ms
+83ms ║RunTime Analysis CS &gt; 25ms &gt; PS &gt; 7ms &gt; PE &gt; 52ms &gt; CE
+86ms ║Runtime (40239 bytes) successfully initialized in 7ms (v0.3.110.20191009) (84ms)
+87ms ║╔Execution stage started
+99ms ║║Condition #3 evaluated false (8ms)
+108ms ║║Condition #5 evaluated false (8ms)
+109ms ║║Condition group #2 evaluated false (state did not change) (18ms)
+110ms ║║Condition group #1 evaluated false (state did not change) (20ms)
+115ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+116ms ║║Condition #13 evaluated false (4ms)
+117ms ║║Condition group #12 evaluated false (state did not change) (5ms)
+119ms ║╚Execution stage complete. (33ms)
+120ms ║Setting up scheduled job for Thu, May 6 2021 @ 9:00:19 PM EDT (in 101.343s)
+177ms ╚Event processed successfully (177ms)
5/6/2021, 8:58:37 PM +406ms
+2ms ╔Received event [Aa Foyer Motion Sensor].motion = inactive with a delay of 143ms
+87ms ║RunTime Analysis CS &gt; 26ms &gt; PS &gt; 6ms &gt; PE &gt; 54ms &gt; CE
+89ms ║Runtime (40239 bytes) successfully initialized in 6ms (v0.3.110.20191009) (87ms)
+90ms ║╔Execution stage started
+101ms ║║Condition #3 evaluated false (6ms)
+105ms ║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+106ms ║║Condition #5 evaluated false (4ms)
+107ms ║║Condition group #2 evaluated false (state did not change) (12ms)
+108ms ║║Condition group #1 evaluated false (state did not change) (14ms)
+118ms ║║Cancelling condition #13's schedules...
+119ms ║║Condition #13 evaluated false (8ms)
+120ms ║║Cancelling condition #12's schedules...
+121ms ║║Condition group #12 evaluated false (state changed) (11ms)
+150ms ║║Executed physical command [null].off() (13ms)
+151ms ║║Executed [foyer virtual switch].off (15ms)
+161ms ║║Condition #13 evaluated false (7ms)
+162ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+164ms ║╚Execution stage complete. (74ms)
+165ms ║Setting up scheduled job for Thu, May 6 2021 @ 9:00:19 PM EDT (in 101.768s)
+172ms ╚Event processed successfully (172ms)
5/6/2021, 8:58:19 PM +173ms
+2ms ╔Received event [foyer virtual switch].switch = on with a delay of 130ms
+85ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 11ms &gt; PE &gt; 52ms &gt; CE
+88ms ║Runtime (40232 bytes) successfully initialized in 11ms (v0.3.110.20191009) (85ms)
+89ms ║╔Execution stage started
+100ms ║║Condition #3 evaluated false (6ms)
+108ms ║║Cancelling condition #5's schedules...
+109ms ║║Condition #5 evaluated false (8ms)
+110ms ║║Cancelling condition #2's schedules...
+111ms ║║Condition group #2 evaluated false (state changed) (17ms)
+112ms ║║Cancelling condition #1's schedules...
+113ms ║║Condition group #1 evaluated false (state changed) (20ms)
+119ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+121ms ║║Cancelling condition #13's schedules...
+121ms ║║Condition #13 evaluated true (5ms)
+123ms ║║Cancelling condition #12's schedules...
+124ms ║║Condition group #12 evaluated true (state changed) (7ms)
+126ms ║║Cancelling statement #14's schedules...
+159ms ║║Executed physical command [Front Foyer Chandelier].setLevel([78]) (29ms)
+160ms ║║Executed [Front Foyer Chandelier].setLevel (31ms)
+164ms ║║Executed virtual command [Front Foyer Chandelier].wait (1ms)
+165ms ║║Requesting a wake up for Thu, May 6 2021 @ 9:00:19 PM EDT (in 120.0s)
+170ms ║╚Execution stage complete. (82ms)
+172ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:58:28 PM EDT (in 9.195s), with 1 more job pending
+185ms ╚Event processed successfully (184ms)
5/6/2021, 8:58:18 PM +343ms
+2ms ╔Received event [Aa Foyer Motion Sensor].motion = active with a delay of 126ms
+98ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 7ms &gt; PE &gt; 69ms &gt; CE
+101ms ║Runtime (40243 bytes) successfully initialized in 7ms (v0.3.110.20191009) (98ms)
+101ms ║╔Execution stage started
+112ms ║║Condition #3 evaluated false (6ms)
+116ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+118ms ║║Cancelling condition #5's schedules...
+119ms ║║Condition #5 evaluated true (5ms)
+120ms ║║Cancelling condition #2's schedules...
+120ms ║║Condition group #2 evaluated true (state changed) (14ms)
+160ms ║║Comparison (time) 75498464 is_between (time) 1620345060000 .. (time) 1620293820000 = true (8ms)
+162ms ║║Time restriction check passed
+163ms ║║Condition #18 evaluated true (42ms)
+172ms ║║Comparison (enum) off is (string) off = true (1ms)
+173ms ║║Condition #21 evaluated true (9ms)
+174ms ║║Cancelling condition #1's schedules...
+175ms ║║Condition group #1 evaluated true (state changed) (70ms)
+177ms ║║Cancelling statement #8's schedules...
+190ms ║║Executed physical command [null].on() (11ms)
+191ms ║║Executed [foyer virtual switch].on (13ms)
+194ms ║║Executed virtual command [foyer virtual switch].wait (1ms)
+195ms ║║Requesting a wake up for Thu, May 6 2021 @ 8:58:28 PM EDT (in 10.0s)
+199ms ║╚Execution stage complete. (98ms)
+200ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:58:28 PM EDT (in 9.996s)
+208ms ╚Event processed successfully (207ms)
5/6/2021, 8:57:04 PM +79ms
+0ms ╔Received event [Charles St].time = 1620349024475 with a delay of -397ms
+76ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 6ms &gt; PE &gt; 51ms &gt; CE
+78ms ║Runtime (40237 bytes) successfully initialized in 6ms (v0.3.110.20191009) (77ms)
+79ms ║╔Execution stage started
+114ms ║║Executed physical command [Front Foyer Chandelier].off() (19ms)
+115ms ║║Executed [Front Foyer Chandelier].off (21ms)
+117ms ║╚Execution stage complete. (38ms)
+118ms ╚Event processed successfully (119ms)
5/6/2021, 8:55:46 PM +932ms
+0ms ╔Received event [Charles St].execute = recovery with a delay of 127ms
+10112ms ║RunTime Analysis CS &gt; 21ms &gt; PS &gt; 10020ms &gt; PE &gt; 65ms &gt; CE
+10113ms ║Piston waited at a semaphore for 10014ms
+10115ms ║Runtime (40317 bytes) successfully initialized in 10020ms (v0.3.110.20191009) (10114ms)
+10116ms ║╔Execution stage started
+10208ms ║║Condition #3 evaluated false (87ms)
+10215ms ║║Condition #5 evaluated false (6ms)
+10216ms ║║Condition group #2 evaluated false (state did not change) (96ms)
+10217ms ║║Condition group #1 evaluated false (state did not change) (97ms)
+10226ms ║║Condition #13 evaluated false (6ms)
+10227ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+10228ms ║╚Execution stage complete. (112ms)
+10230ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 67.314s)
+10240ms ╚Event processed successfully (10240ms)
5/6/2021, 8:55:46 PM +949ms
+0ms ╔Received event [Charles St].execute = recovery with a delay of 50ms
+10094ms ║RunTime Analysis CS &gt; 14ms &gt; PS &gt; 10024ms &gt; PE &gt; 55ms &gt; CE
+10095ms ║Piston waited at a semaphore for 10020ms
+10097ms ║Runtime (40316 bytes) successfully initialized in 10024ms (v0.3.110.20191009) (10096ms)
+10098ms ║╔Execution stage started
+10108ms ║║Condition #3 evaluated false (6ms)
+10115ms ║║Condition #5 evaluated false (6ms)
+10116ms ║║Condition group #2 evaluated false (state did not change) (14ms)
+10117ms ║║Condition group #1 evaluated false (state did not change) (16ms)
+10125ms ║║Condition #13 evaluated false (6ms)
+10126ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+10128ms ║╚Execution stage complete. (31ms)
+10129ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 67.397s)
+10139ms ╚Event processed successfully (10139ms)
5/6/2021, 8:55:46 PM +876ms
+0ms ╔Received event [Charles St].execute = recovery with a delay of 119ms
+10134ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 10010ms &gt; PE &gt; 101ms &gt; CE
+10135ms ║Piston waited at a semaphore for 10004ms
+10138ms ║Runtime (40318 bytes) successfully initialized in 10010ms (v0.3.110.20191009) (10136ms)
+10139ms ║╔Execution stage started
+10152ms ║║Condition #3 evaluated false (8ms)
+10159ms ║║Condition #5 evaluated false (6ms)
+10160ms ║║Condition group #2 evaluated false (state did not change) (17ms)
+10161ms ║║Condition group #1 evaluated false (state did not change) (18ms)
+10171ms ║║Condition #13 evaluated false (7ms)
+10172ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+10174ms ║╚Execution stage complete. (36ms)
+10175ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 67.424s)
+10187ms ╚Event processed successfully (10187ms)
5/6/2021, 8:55:46 PM +770ms
+0ms ╔Received event [Charles St].execute = recovery with a delay of 123ms
+10128ms ║RunTime Analysis CS &gt; 25ms &gt; PS &gt; 10023ms &gt; PE &gt; 80ms &gt; CE
+10130ms ║Piston waited at a semaphore for 10018ms
+10132ms ║Runtime (40317 bytes) successfully initialized in 10023ms (v0.3.110.20191009) (10131ms)
+10133ms ║╔Execution stage started
+10146ms ║║Condition #3 evaluated false (7ms)
+10154ms ║║Condition #5 evaluated false (8ms)
+10155ms ║║Condition group #2 evaluated false (state did not change) (17ms)
+10157ms ║║Condition group #1 evaluated false (state did not change) (20ms)
+10168ms ║║Condition #13 evaluated false (8ms)
+10169ms ║║Condition group #12 evaluated false (state did not change) (9ms)
+10171ms ║╚Execution stage complete. (38ms)
+10173ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 67.533s)
+10181ms ╚Event processed successfully (10181ms)
5/6/2021, 8:55:46 PM +741ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 51ms
+10087ms ║RunTime Analysis CS &gt; 15ms &gt; PS &gt; 10021ms &gt; PE &gt; 50ms &gt; CE
+10088ms ║Piston waited at a semaphore for 10016ms
+10090ms ║Runtime (40316 bytes) successfully initialized in 10021ms (v0.3.110.20191009) (10089ms)
+10091ms ║╔Execution stage started
+10101ms ║║Condition #3 evaluated false (6ms)
+10108ms ║║Condition #5 evaluated false (6ms)
+10109ms ║║Condition group #2 evaluated false (state did not change) (14ms)
+10110ms ║║Condition group #1 evaluated false (state did not change) (16ms)
+10119ms ║║Condition #13 evaluated false (6ms)
+10120ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+10121ms ║╚Execution stage complete. (31ms)
+10123ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 67.612s)
+10134ms ╚Event processed successfully (10134ms)
5/6/2021, 8:55:46 PM +709ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 61ms
+10088ms ║RunTime Analysis CS &gt; 15ms &gt; PS &gt; 10022ms &gt; PE &gt; 51ms &gt; CE
+10089ms ║Piston waited at a semaphore for 10017ms
+10091ms ║Runtime (40316 bytes) successfully initialized in 10022ms (v0.3.110.20191009) (10090ms)
+10092ms ║╔Execution stage started
+10103ms ║║Condition #3 evaluated false (6ms)
+10110ms ║║Condition #5 evaluated false (6ms)
+10111ms ║║Condition group #2 evaluated false (state did not change) (14ms)
+10112ms ║║Condition group #1 evaluated false (state did not change) (16ms)
+10121ms ║║Condition #13 evaluated false (6ms)
+10122ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+10124ms ║╚Execution stage complete. (32ms)
+10125ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 67.641s)
+10137ms ╚Event processed successfully (10137ms)
5/6/2021, 8:55:46 PM +897ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 121ms
+93ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 11ms &gt; PE &gt; 60ms &gt; CE
+95ms ║Runtime (40233 bytes) successfully initialized in 11ms (v0.3.110.20191009) (94ms)
+96ms ║╔Execution stage started
+109ms ║║Condition #3 evaluated false (8ms)
+118ms ║║Condition #5 evaluated false (8ms)
+119ms ║║Condition group #2 evaluated false (state did not change) (18ms)
+120ms ║║Condition group #1 evaluated false (state did not change) (20ms)
+129ms ║║Cancelling condition #13's schedules...
+130ms ║║Condition #13 evaluated false (7ms)
+131ms ║║Cancelling condition #12's schedules...
+131ms ║║Condition group #12 evaluated false (state changed) (9ms)
+134ms ║╚Execution stage complete. (37ms)
+135ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 77.444s)
+150ms ╚Event processed successfully (149ms)
5/6/2021, 8:55:46 PM +672ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 119ms
+96ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 8ms &gt; PE &gt; 70ms &gt; CE
+98ms ║Runtime (40228 bytes) successfully initialized in 8ms (v0.3.110.20191009) (97ms)
+99ms ║╔Execution stage started
+112ms ║║Condition #3 evaluated false (8ms)
+120ms ║║Condition #5 evaluated false (7ms)
+121ms ║║Condition group #2 evaluated false (state did not change) (17ms)
+122ms ║║Condition group #1 evaluated false (state did not change) (19ms)
+131ms ║║Cancelling condition #13's schedules...
+132ms ║║Condition #13 evaluated false (8ms)
+133ms ║║Cancelling condition #12's schedules...
+134ms ║║Condition group #12 evaluated false (state changed) (10ms)
+162ms ║║Executed physical command [null].off() (12ms)
+163ms ║║Executed [foyer virtual switch].off (14ms)
+173ms ║║Condition #13 evaluated false (7ms)
+174ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+176ms ║╚Execution stage complete. (77ms)
+177ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 77.626s)
+192ms ╚Event processed successfully (192ms)
5/6/2021, 8:55:46 PM +664ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 55ms
+91ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 6ms &gt; PE &gt; 65ms &gt; CE
+94ms ║Runtime (40227 bytes) successfully initialized in 6ms (v0.3.110.20191009) (92ms)
+95ms ║╔Execution stage started
+107ms ║║Condition #3 evaluated false (6ms)
+114ms ║║Condition #5 evaluated false (7ms)
+115ms ║║Condition group #2 evaluated false (state did not change) (15ms)
+116ms ║║Condition group #1 evaluated false (state did not change) (17ms)
+126ms ║║Cancelling condition #13's schedules...
+127ms ║║Condition #13 evaluated false (8ms)
+128ms ║║Cancelling condition #12's schedules...
+128ms ║║Condition group #12 evaluated false (state changed) (9ms)
+147ms ║║Executed physical command [null].off() (6ms)
+148ms ║║Executed [foyer virtual switch].off (8ms)
+157ms ║║Condition #13 evaluated false (6ms)
+158ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+160ms ║╚Execution stage complete. (65ms)
+162ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:57:04 PM EDT (in 77.65s)
+169ms ╚Event processed successfully (169ms)
5/6/2021, 8:55:04 PM +304ms
+2ms ╔Received event [foyer virtual switch].switch = on with a delay of 140ms
+80ms ║RunTime Analysis CS &gt; 19ms &gt; PS &gt; 8ms &gt; PE &gt; 53ms &gt; CE
+83ms ║Runtime (40231 bytes) successfully initialized in 8ms (v0.3.110.20191009) (80ms)
+84ms ║╔Execution stage started
+96ms ║║Condition #3 evaluated false (7ms)
+104ms ║║Cancelling condition #5's schedules...
+105ms ║║Condition #5 evaluated false (8ms)
+106ms ║║Cancelling condition #2's schedules...
+107ms ║║Condition group #2 evaluated false (state changed) (18ms)
+108ms ║║Cancelling condition #1's schedules...
+109ms ║║Condition group #1 evaluated false (state changed) (21ms)
+115ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+116ms ║║Cancelling condition #13's schedules...
+117ms ║║Condition #13 evaluated true (5ms)
+118ms ║║Cancelling condition #12's schedules...
+119ms ║║Condition group #12 evaluated true (state changed) (8ms)
+121ms ║║Cancelling statement #14's schedules...
+162ms ║║Executed physical command [Front Foyer Chandelier].setLevel([78]) (36ms)
+163ms ║║Executed [Front Foyer Chandelier].setLevel (38ms)
+168ms ║║Executed virtual command [Front Foyer Chandelier].wait (1ms)
+170ms ║║Requesting a wake up for Thu, May 6 2021 @ 8:57:04 PM EDT (in 120.0s)
+176ms ║╚Execution stage complete. (93ms)
+179ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:55:13 PM EDT (in 9.444s), with 1 more job pending
+189ms ╚Event processed successfully (189ms)
5/6/2021, 8:55:03 PM +741ms
+1ms ╔Received event [Aa Foyer Motion Sensor].motion = active with a delay of 72ms
+82ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 5ms &gt; PE &gt; 61ms &gt; CE
+85ms ║Runtime (40244 bytes) successfully initialized in 5ms (v0.3.110.20191009) (82ms)
+86ms ║╔Execution stage started
+104ms ║║Condition #3 evaluated false (13ms)
+108ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+109ms ║║Cancelling condition #5's schedules...
+110ms ║║Condition #5 evaluated true (5ms)
+111ms ║║Cancelling condition #2's schedules...
+113ms ║║Condition group #2 evaluated true (state changed) (22ms)
+154ms ║║Comparison (time) 75303855 is_between (time) 1620345060000 .. (time) 1620293820000 = true (9ms)
+155ms ║║Time restriction check passed
+156ms ║║Condition #18 evaluated true (43ms)
+164ms ║║Comparison (enum) off is (string) off = true (1ms)
+165ms ║║Condition #21 evaluated true (8ms)
+166ms ║║Cancelling condition #1's schedules...
+167ms ║║Condition group #1 evaluated true (state changed) (77ms)
+169ms ║║Cancelling statement #8's schedules...
+179ms ║║Executed physical command [null].on() (6ms)
+180ms ║║Executed [foyer virtual switch].on (8ms)
+183ms ║║Executed virtual command [foyer virtual switch].wait (1ms)
+184ms ║║Requesting a wake up for Thu, May 6 2021 @ 8:55:13 PM EDT (in 10.0s)
+188ms ║╚Execution stage complete. (103ms)
+190ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:55:13 PM EDT (in 9.996s)
+197ms ╚Event processed successfully (197ms)
5/6/2021, 8:54:52 PM +501ms
+2ms ╔Received event [Aa Foyer Motion Sensor].motion = inactive with a delay of 172ms
+108ms ║RunTime Analysis CS &gt; 26ms &gt; PS &gt; 9ms &gt; PE &gt; 73ms &gt; CE
+111ms ║Runtime (40248 bytes) successfully initialized in 9ms (v0.3.110.20191009) (107ms)
+111ms ║╔Execution stage started
+123ms ║║Condition #3 evaluated false (6ms)
+126ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+128ms ║║Condition #5 evaluated false (5ms)
+129ms ║║Condition group #2 evaluated false (state did not change) (13ms)
+130ms ║║Condition group #1 evaluated false (state did not change) (14ms)
+139ms ║║Condition #13 evaluated false (7ms)
+140ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+142ms ║╚Execution stage complete. (30ms)
+143ms ╚Event processed successfully (142ms)
5/6/2021, 8:54:33 PM +120ms
+0ms ╔Received event [Charles St].time = 1620348874650 with a delay of -1531ms
+76ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 6ms &gt; PE &gt; 51ms &gt; CE
+79ms ║Runtime (40240 bytes) successfully initialized in 6ms (v0.3.110.20191009) (78ms)
+80ms ║╔Execution stage started
+100ms ║║Skipped execution of physical command [Front Foyer Chandelier].off([]) because it would make no change to the device. (4ms)
+101ms ║║Executed [Front Foyer Chandelier].off (6ms)
+103ms ║╚Execution stage complete. (24ms)
+104ms ╚Event processed successfully (104ms)
5/6/2021, 8:53:44 PM +844ms
+1ms ╔Received event [Aa Foyer Motion Sensor].motion = inactive with a delay of 69ms
+67ms ║RunTime Analysis CS &gt; 15ms &gt; PS &gt; 6ms &gt; PE &gt; 47ms &gt; CE
+69ms ║Runtime (40246 bytes) successfully initialized in 6ms (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)
+85ms ║║Condition #5 evaluated false (4ms)
+86ms ║║Condition group #2 evaluated false (state did not change) (12ms)
+87ms ║║Condition group #1 evaluated false (state did not change) (13ms)
+95ms ║║Condition #13 evaluated false (6ms)
+96ms ║║Condition group #12 evaluated false (state did not change) (7ms)
+98ms ║╚Execution stage complete. (28ms)
+99ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:54:34 PM EDT (in 49.708s)
+111ms ╚Event processed successfully (111ms)
5/6/2021, 8:52:52 PM +87ms
+1ms ╔Received event [Aa Foyer Motion Sensor].motion = inactive with a delay of 76ms
+76ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 5ms &gt; PE &gt; 48ms &gt; CE
+79ms ║Runtime (40244 bytes) successfully initialized in 5ms (v0.3.110.20191009) (76ms)
+79ms ║╔Execution stage started
+90ms ║║Condition #3 evaluated false (6ms)
+94ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+95ms ║║Condition #5 evaluated false (4ms)
+96ms ║║Condition group #2 evaluated false (state did not change) (12ms)
+97ms ║║Condition group #1 evaluated false (state did not change) (14ms)
+106ms ║║Condition #13 evaluated false (7ms)
+107ms ║║Condition group #12 evaluated false (state did not change) (8ms)
+109ms ║╚Execution stage complete. (30ms)
+110ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:54:34 PM EDT (in 102.453s)
+118ms ╚Event processed successfully (118ms)
5/6/2021, 8:52:43 PM +822ms
+2ms ╔Received event [foyer virtual switch].switch = off with a delay of 147ms
+80ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 6ms &gt; PE &gt; 50ms &gt; CE
+82ms ║Runtime (40237 bytes) successfully initialized in 6ms (v0.3.110.20191009) (79ms)
+83ms ║╔Execution stage started
+94ms ║║Condition #3 evaluated false (6ms)
+100ms ║║Condition #5 evaluated false (6ms)
+101ms ║║Condition group #2 evaluated false (state did not change) (14ms)
+102ms ║║Condition group #1 evaluated false (state did not change) (16ms)
+107ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+108ms ║║Condition #13 evaluated false (4ms)
+109ms ║║Condition group #12 evaluated false (state did not change) (5ms)
+111ms ║╚Execution stage complete. (29ms)
+112ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:54:34 PM EDT (in 110.716s)
+123ms ╚Event processed successfully (123ms)
5/6/2021, 8:52:43 PM +89ms
+0ms ╔Received event [Charles St].time = 1620348764051 with a delay of -962ms
+73ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 6ms &gt; PE &gt; 50ms &gt; CE
+75ms ║Runtime (40231 bytes) successfully initialized in 6ms (v0.3.110.20191009) (74ms)
+76ms ║╔Execution stage started
+94ms ║║Executed physical command [null].off() (6ms)
+95ms ║║Executed [foyer virtual switch].off (8ms)
+103ms ║║Cancelling condition #13's schedules...
+104ms ║║Condition #13 evaluated false (6ms)
+105ms ║║Cancelling condition #12's schedules...
+105ms ║║Condition group #12 evaluated false (state changed) (7ms)
+108ms ║╚Execution stage complete. (32ms)
+109ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:54:34 PM EDT (in 111.452s)
+116ms ╚Event processed successfully (116ms)
5/6/2021, 8:52:34 PM +497ms
+2ms ╔Received event [foyer virtual switch].switch = on with a delay of 121ms
+97ms ║RunTime Analysis CS &gt; 26ms &gt; PS &gt; 9ms &gt; PE &gt; 61ms &gt; CE
+99ms ║Runtime (40231 bytes) successfully initialized in 9ms (v0.3.110.20191009) (97ms)
+100ms ║╔Execution stage started
+111ms ║║Condition #3 evaluated false (6ms)
+120ms ║║Cancelling condition #5's schedules...
+120ms ║║Condition #5 evaluated false (8ms)
+122ms ║║Cancelling condition #2's schedules...
+122ms ║║Condition group #2 evaluated false (state changed) (17ms)
+123ms ║║Cancelling condition #1's schedules...
+124ms ║║Condition group #1 evaluated false (state changed) (20ms)
+130ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+131ms ║║Cancelling condition #13's schedules...
+132ms ║║Condition #13 evaluated true (5ms)
+133ms ║║Cancelling condition #12's schedules...
+134ms ║║Condition group #12 evaluated true (state changed) (7ms)
+136ms ║║Cancelling statement #14's schedules...
+148ms ║║Skipped execution of physical command [Front Foyer Chandelier].setLevel([78]) because it would make no change to the device. (7ms)
+149ms ║║Executed [Front Foyer Chandelier].setLevel (9ms)
+152ms ║║Executed virtual command [Front Foyer Chandelier].wait (0ms)
+153ms ║║Requesting a wake up for Thu, May 6 2021 @ 8:54:34 PM EDT (in 120.0s)
+158ms ║╚Execution stage complete. (58ms)
+160ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:52:44 PM EDT (in 9.395s), with 1 more job pending
+169ms ╚Event processed successfully (169ms)
5/6/2021, 8:52:33 PM +889ms
+1ms ╔Received event [Aa Foyer Motion Sensor].motion = active with a delay of 73ms
+70ms ║RunTime Analysis CS &gt; 15ms &gt; PS &gt; 5ms &gt; PE &gt; 50ms &gt; CE
+73ms ║Runtime (40244 bytes) successfully initialized in 5ms (v0.3.110.20191009) (70ms)
+73ms ║╔Execution stage started
+84ms ║║Condition #3 evaluated false (6ms)
+88ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+89ms ║║Cancelling condition #5's schedules...
+90ms ║║Condition #5 evaluated true (5ms)
+91ms ║║Cancelling condition #2's schedules...
+92ms ║║Condition group #2 evaluated true (state changed) (14ms)
+131ms ║║Comparison (time) 75153982 is_between (time) 1620345060000 .. (time) 1620293820000 = true (9ms)
+132ms ║║Time restriction check passed
+134ms ║║Condition #18 evaluated true (41ms)
+141ms ║║Comparison (enum) off is (string) off = true (2ms)
+142ms ║║Condition #21 evaluated true (8ms)
+143ms ║║Cancelling condition #1's schedules...
+144ms ║║Condition group #1 evaluated true (state changed) (67ms)
+146ms ║║Cancelling statement #8's schedules...
+157ms ║║Executed physical command [null].on() (8ms)
+157ms ║║Executed [foyer virtual switch].on (9ms)
+161ms ║║Executed virtual command [foyer virtual switch].wait (0ms)
+162ms ║║Requesting a wake up for Thu, May 6 2021 @ 8:52:44 PM EDT (in 10.0s)
+166ms ║╚Execution stage complete. (93ms)
+168ms ║Setting up scheduled job for Thu, May 6 2021 @ 8:52:44 PM EDT (in 9.995s), with 1 more job pending
+184ms ╚Event processed successfully (184ms)
5/6/2021, 8:52:07 PM +597ms
+1ms ╔Received event [Aa Foyer Motion Sensor].motion = inactive with a delay of 144ms
+86ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 6ms &gt; PE &gt; 62ms &gt; CE
+88ms ║Runtime (40245 bytes) successfully initialized in 6ms (v0.3.110.20191009) (86ms)
+89ms ║╔Execution stage started`Preformatted text`

REMOVE BELOW AFTER READING
If a solution is found for your question then please mark the post as the solution.

eibyer · 2021-05-07 13:53:09 UTC

First look and I’m noticing you have TCP to Never Cancel. If you want the motion to keep resetting the timer, that should be left on Default so the timer keeps getting extended every time the motion gets retriggered.

Robin · 2021-05-08 10:11:31 UTC

It’s hard to review a piston in the format provided.

Please use the green snapshot button rather than an edited screenshot. That way we can see your device subscriptions and anonymous device names,

fredfon · 2021-05-10 00:31:45 UTC

fredfon · 2021-05-10 00:33:29 UTC

That is what I get when using the green button.

orangebucket · 2021-05-10 10:26:39 UTC

I do notice the logs look a bit odd for the virtual switch, as they say null instead of the device name. Not sure what is going on there.

As the names are blanked out it is a little hard to follow the logic. If I were doing it I think I’d trigger the 2 minutes based on an absence of motion (using conditions not triggers). That way whenever there is motion the timer would be cancelled.

fredfon · 2021-05-11 00:14:00 UTC

Are you saying you wouldn’t use a virtual switch at all?

orangebucket · 2021-05-11 05:48:35 UTC

Correct. I may have missed something but it doesn’t sound like you ought to need one.

fredfon · 2021-05-13 12:07:11 UTC

You are correct, I wasn’t completely understanding TCP and I was trying to re-invent the wheel.
Thanks