Motion Activated Lighting not Working

[mastermc0]

1) Give a description of the problem
Light stays on after timeout

2) What is the expected behavior?
Light should turn off after there has been no motion after 2 minutes

3) What is happening/not happening?
The light switches on as expected but does not turn off.

**4) Post a Green Snapshot of the piston!

**5) 22/01/2019, 21:14:03 +782ms
+1ms ╔Starting piston… (v0.3.109.20181207)
+284ms ║╔Subscribing to devices…
+354ms ║║Subscribing to Bathroom Sensor.motion…
+369ms ║║Subscribing to Bathroom Spot 1.switch…
+385ms ║║Subscribing to Bathroom Spot 2.switch…
+400ms ║║Subscribing to Bathroom Spot 3.switch…
+414ms ║║Subscribing to Bathroom Spot 4.switch…
+510ms ║║Subscribing to Bathroom Door…
+512ms ║╚Finished subscribing (246ms)
+566ms ║Comparison (enum) off is (string) off = true (2ms)
+578ms ║Comparison (string) :4929cbc8929e233a4a9100d2f595edfb: is_not (string) :85be758d258a40390d4eeb1504b3b5c4: = true (2ms)
+602ms ║Comparison (enum) inactive stays (string) inactive = true (2ms)
+604ms ║Cancelling condition #12’s schedules…
+610ms ║Comparison (boolean) false is (boolean) true = false (2ms)
+623ms ║Comparison (enum) open is (string) open = true (3ms)
+661ms ║Comparison (boolean) false is (boolean) true = false (2ms)
+703ms ╚Piston successfully started (702ms)
22/01/2019, 20:43:39 +626ms
+1ms ╔Starting piston… (v0.3.109.20181207)
+292ms ║╔Subscribing to devices…
+361ms ║║Subscribing to Bathroom Sensor.motion…
+373ms ║║Subscribing to Bathroom Spot 1.switch…
+385ms ║║Subscribing to Bathroom Spot 2.switch…
+398ms ║║Subscribing to Bathroom Spot 3.switch…
+411ms ║║Subscribing to Bathroom Spot 4.switch…
+543ms ║║Subscribing to Bathroom Door…
+545ms ║╚Finished subscribing (256ms)
+990ms ║Comparison (enum) off is (string) off = true (2ms)
+1003ms ║Comparison (string) :4929cbc8929e233a4a9100d2f595edfb: is_not (string) :85be758d258a40390d4eeb1504b3b5c4: = true (2ms)
+1031ms ║Comparison (boolean) false is (boolean) true = false (2ms)
+1043ms ║Comparison (enum) open is (string) open = true (2ms)
+1094ms ║Comparison (boolean) false is (boolean) true = false (2ms)
+1096ms ║Cancelling condition #30’s schedules…
+1098ms ║Cancelling condition #27’s schedules…
+1143ms ╚Piston successfully started (1143ms)
22/01/2019, 20:40:12 +480ms
+138ms ╔Stopping piston…
+249ms ╚Piston successfully stopped (111ms)
22/01/2019, 20:39:40 +652ms
+1ms ╔Received event [Bathroom Spot 4].switch = off with a delay of 367ms
+9906ms ║RunTime Analysis CS > 22ms > PS > 9818ms > PE > 66ms > CE
+9908ms ║Piston waited at a semaphore for 9768ms
+9910ms ║Runtime (45685 bytes) successfully initialized in 9818ms (v0.3.109.20181207) (9908ms)
+9911ms ║╔Execution stage started
+9925ms ║║Condition #5 evaluated false (8ms)
+9926ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+9936ms ║║Condition #12 evaluated false (6ms)
+9938ms ║║Condition group #8 evaluated false (state did not change) (8ms)
+9958ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+9961ms ║║Condition #18 evaluated false (19ms)
+9962ms ║║Condition group #14 evaluated false (state did not change) (22ms)
+9982ms ║║Comparison (enum) off changes_to (string) off = false (1ms)
+9985ms ║║Cancelling condition #26’s schedules…
+9986ms ║║Condition #26 evaluated false (21ms)
+9988ms ║║Cancelling condition #23’s schedules…
+9989ms ║║Condition group #23 evaluated false (state changed) (23ms)
+9991ms ║╚Execution stage complete. (80ms)
+9993ms ╚Event processed successfully (9993ms)
22/01/2019, 20:39:40 +800ms
+1ms ╔Received event [Bathroom Spot 2].switch = off with a delay of 362ms
+132ms ║RunTime Analysis CS > 24ms > PS > 48ms > PE > 61ms > CE
+135ms ║Runtime (45609 bytes) successfully initialized in 48ms (v0.3.109.20181207) (133ms)
+136ms ║╔Execution stage started
+152ms ║║Condition #5 evaluated false (8ms)
+154ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+168ms ║║Condition #12 evaluated false (9ms)
+170ms ║║Condition group #8 evaluated false (state did not change) (11ms)
+195ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+200ms ║║Condition #18 evaluated false (25ms)
+201ms ║║Condition group #14 evaluated false (state did not change) (27ms)
+223ms ║║Comparison (enum) off changes_to (string) off = true (1ms)
+227ms ║║Condition #26 evaluated true (20ms)
+228ms ║║Condition group #23 evaluated true (state did not change) (23ms)
+232ms ║║Cancelling statement #24’s schedules…
+240ms ║║Executed virtual command setVariable (3ms)
+244ms ║╚Execution stage complete. (108ms)
+246ms ╚Event processed successfully (247ms)
22/01/2019, 20:39:40 +414ms
+2ms ╔Received event [Bathroom Spot 3].switch = off with a delay of 377ms
+137ms ║RunTime Analysis CS > 22ms > PS > 54ms > PE > 61ms > CE
+140ms ║Runtime (45606 bytes) successfully initialized in 54ms (v0.3.109.20181207) (137ms)
+142ms ║╔Execution stage started
+156ms ║║Condition #5 evaluated false (7ms)
+157ms ║║Condition group #1 evaluated false (state did not change) (10ms)
+168ms ║║Condition #12 evaluated false (7ms)
+169ms ║║Condition group #8 evaluated false (state did not change) (9ms)
+192ms ║║Comparison (enum) off changes_to (string) on = false (0ms)
+195ms ║║Condition #18 evaluated false (21ms)
+196ms ║║Condition group #14 evaluated false (state did not change) (24ms)
+215ms ║║Comparison (enum) off changes_to (string) off = true (1ms)
+218ms ║║Condition #26 evaluated true (18ms)
+220ms ║║Condition group #23 evaluated true (state did not change) (20ms)
+223ms ║║Cancelling statement #24’s schedules…
+229ms ║║Executed virtual command setVariable (3ms)
+232ms ║╚Execution stage complete. (91ms)
+234ms ╚Event processed successfully (234ms)
22/01/2019, 20:39:39 +946ms
+1ms ╔Received event [Bathroom Spot 1].switch = off with a delay of 334ms
+126ms ║RunTime Analysis CS > 15ms > PS > 49ms > PE > 62ms > CE
+129ms ║Runtime (45607 bytes) successfully initialized in 49ms (v0.3.109.20181207) (127ms)
+130ms ║╔Execution stage started
+145ms ║║Condition #5 evaluated false (9ms)
+147ms ║║Condition group #1 evaluated false (state did not change) (10ms)
+158ms ║║Cancelling condition #12’s schedules…
+166ms ║║Condition #12 evaluated false (9ms)
+167ms ║║Condition group #8 evaluated false (state did not change) (17ms)
+193ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+196ms ║║Condition #18 evaluated false (25ms)
+198ms ║║Condition group #14 evaluated false (state did not change) (27ms)
+219ms ║║Comparison (enum) off changes_to (string) off = true (1ms)
+221ms ║║Cancelling condition #26’s schedules…
+222ms ║║Condition #26 evaluated true (21ms)
+224ms ║║Cancelling condition #23’s schedules…
+225ms ║║Condition group #23 evaluated true (state changed) (24ms)
+228ms ║║Cancelling statement #24’s schedules…
+235ms ║║Executed virtual command setVariable (3ms)
+238ms ║╚Execution stage complete. (108ms)
+240ms ╚Event processed successfully (240ms)

[guxdude]

What is contact sensor 6 doing? That is the only thing not in this piston that could prevent the lights from turning off.

[Bruce_Young]

If you turn on “Trace” and then take a Green Snapshot, it is much easier to try to figure out what is going on in the Log. Without that, one has to guess at what statements the log is referring to.

[mastermc0]

I’ve changed the piston ever so slightly but its made no difference. New log attached too.

23/01/2019, 09:47:58 +95ms
+0ms ╔Received event [Home].time = 1548236879772 with a delay of -1678ms
+182ms ║RunTime Analysis CS > 21ms > PS > 70ms > PE > 91ms > CE
+185ms ║Runtime (45778 bytes) successfully initialized in 70ms (v0.3.109.20181207) (184ms)
+186ms ║╔Execution stage started
+209ms ║║Cancelling condition #12’s schedules…
+210ms ║║Condition #12 evaluated true (2ms)
+217ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+220ms ║║Condition #13 evaluated true (8ms)
+230ms ║║Comparison (enum) open is (string) open = true (2ms)
+233ms ║║Condition #40 evaluated true (11ms)
+234ms ║║Cancelling condition #8’s schedules…
+236ms ║║Condition group #8 evaluated true (state changed) (28ms)
+239ms ║║Cancelling statement #9’s schedules…
+248ms ║║Skipped execution of physical command [Bathroom Spot 1].off([]) because it would make no change to the device. (2ms)
+249ms ║║Executed [Bathroom Spot 1].off (6ms)
+255ms ║║Skipped execution of physical command [Bathroom Spot 2].off([]) because it would make no change to the device. (3ms)
+256ms ║║Executed [Bathroom Spot 2].off (5ms)
+262ms ║║Skipped execution of physical command [Bathroom Spot 3].off([]) because it would make no change to the device. (3ms)
+264ms ║║Executed [Bathroom Spot 3].off (5ms)
+270ms ║║Skipped execution of physical command [Bathroom Spot 4].off([]) because it would make no change to the device. (3ms)
+272ms ║║Executed [Bathroom Spot 4].off (6ms)
+296ms ║║Condition #18 evaluated false (20ms)
+298ms ║║Condition group #14 evaluated false (state did not change) (21ms)
+351ms ║║Condition #26 evaluated false (49ms)
+353ms ║║Condition group #23 evaluated false (state did not change) (52ms)
+356ms ║╚Execution stage complete. (170ms)
+358ms ╚Event processed successfully (359ms)
23/01/2019, 09:45:59 +576ms
+1ms ╔Received event [Home].test = 1548236759575 with a delay of 1ms
+147ms ║RunTime Analysis CS > 21ms > PS > 45ms > PE > 81ms > CE
+151ms ║Runtime (45772 bytes) successfully initialized in 45ms (v0.3.109.20181207) (148ms)
+152ms ║╔Execution stage started
+168ms ║║Condition #5 evaluated false (8ms)
+170ms ║║Condition group #1 evaluated false (state did not change) (10ms)
+184ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+195ms ║║Adding a timed trigger schedule for condition 12
+201ms ║║Cancelling condition #12’s schedules…
+202ms ║║Condition #12 evaluated false (28ms)
+204ms ║║Cancelling condition #8’s schedules…
+205ms ║║Condition group #8 evaluated false (state changed) (32ms)
+231ms ║║Condition #18 evaluated false (22ms)
+233ms ║║Condition group #14 evaluated false (state did not change) (24ms)
+258ms ║║Condition #26 evaluated false (20ms)
+260ms ║║Condition group #23 evaluated false (state did not change) (22ms)
+272ms ║╚Execution stage complete. (121ms)
+279ms ║Setting up scheduled job for Wed, Jan 23 2019 @ 9:47:59 AM GMT (in 119.918s)
+288ms ╚Event processed successfully (287ms)
23/01/2019, 09:44:34 +715ms
+1ms ╔Starting piston… (v0.3.109.20181207)
+308ms ║╔Subscribing to devices…
+352ms ║║Subscribing to Bathroom Sensor.motion…
+366ms ║║Subscribing to Bathroom Spot 1.switch…
+382ms ║║Subscribing to Bathroom Spot 2.switch…
+394ms ║║Subscribing to Bathroom Spot 3.switch…
+407ms ║║Subscribing to Bathroom Spot 4.switch…
+502ms ║║Subscribing to Bathroom Door…
+504ms ║╚Finished subscribing (211ms)
+575ms ║Comparison (enum) off is (string) off = true (2ms)
+579ms ║Cancelling condition #6’s schedules…
+593ms ║Comparison (string) :85be758d258a40390d4eeb1504b3b5c4: is_not (string) :85be758d258a40390d4eeb1504b3b5c4: = false (3ms)
+595ms ║Cancelling condition #39’s schedules…
+660ms ║Comparison (enum) inactive stays (string) inactive = true (3ms)
+672ms ║Comparison (boolean) true is (boolean) true = true (4ms)
+687ms ║Comparison (enum) open is (string) open = true (3ms)
+734ms ║Comparison (boolean) false is (boolean) true = false (3ms)
+737ms ║Cancelling condition #30’s schedules…
+739ms ║Cancelling condition #27’s schedules…
+788ms ╚Piston successfully started (788ms)
23/01/2019, 09:02:59 +109ms
+1ms ╔Received event [Home].time = 1548234180408 with a delay of -1300ms
+312ms ║RunTime Analysis CS > 81ms > PS > 164ms > PE > 67ms > CE
+315ms ║Runtime (45568 bytes) successfully initialized in 164ms (v0.3.109.20181207) (312ms)
+316ms ║╔Execution stage started
+338ms ║║Cancelling condition #12’s schedules…
+340ms ║║Condition #12 evaluated true (2ms)
+347ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+350ms ║║Condition #13 evaluated true (8ms)
+360ms ║║Comparison (enum) open is (string) open = true (2ms)
+362ms ║║Condition #40 evaluated true (11ms)
+364ms ║║Cancelling condition #8’s schedules…
+365ms ║║Condition group #8 evaluated true (state changed) (28ms)
+368ms ║║Cancelling statement #9’s schedules…
+378ms ║║Skipped execution of physical command [Bathroom Spot 1].off([]) because it would make no change to the device. (3ms)
+379ms ║║Executed [Bathroom Spot 1].off (6ms)
+386ms ║║Skipped execution of physical command [Bathroom Spot 2].off([]) because it would make no change to the device. (3ms)
+387ms ║║Executed [Bathroom Spot 2].off (5ms)
+393ms ║║Skipped execution of physical command [Bathroom Spot 3].off([]) because it would make no change to the device. (3ms)
+395ms ║║Executed [Bathroom Spot 3].off (6ms)
+401ms ║║Skipped execution of physical command [Bathroom Spot 4].off([]) because it would make no change to the device. (4ms)
+403ms ║║Executed [Bathroom Spot 4].off (6ms)
+428ms ║║Condition #18 evaluated false (20ms)
+430ms ║║Condition group #14 evaluated false (state did not change) (23ms)
+455ms ║║Condition #26 evaluated false (20ms)
+457ms ║║Condition group #23 evaluated false (state did not change) (23ms)
+460ms ║╚Execution stage complete. (144ms)
+462ms ╚Event processed successfully (463ms)
23/01/2019, 09:01:00 +388ms
+2ms ╔Received event [Bathroom Spot 4].switch = off with a delay of 401ms
+10150ms ║RunTime Analysis CS > 15ms > PS > 10072ms > PE > 62ms > CE
+10151ms ║Piston waited at a semaphore for 10019ms
+10154ms ║Runtime (45647 bytes) successfully initialized in 10072ms (v0.3.109.20181207) (10151ms)
+10155ms ║╔Execution stage started
+10170ms ║║Condition #5 evaluated false (7ms)
+10171ms ║║Condition group #1 evaluated false (state did not change) (10ms)
+10184ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+10187ms ║║Condition #12 evaluated false (11ms)
+10188ms ║║Condition group #8 evaluated false (state did not change) (14ms)
+10212ms ║║Comparison (enum) off changes_to (string) on = false (0ms)
+10214ms ║║Condition #18 evaluated false (23ms)
+10216ms ║║Condition group #14 evaluated false (state did not change) (24ms)
+10234ms ║║Comparison (enum) off changes_to (string) off = false (1ms)
+10237ms ║║Condition #26 evaluated false (18ms)
+10238ms ║║Condition group #23 evaluated false (state did not change) (19ms)
+10241ms ║╚Execution stage complete. (85ms)
+10242ms ║Setting up scheduled job for Wed, Jan 23 2019 @ 9:03:00 AM GMT (in 109.778s)
+10254ms ╚Event processed successfully (10254ms)
23/01/2019, 09:01:00 +290ms
+1ms ╔Received event [Bathroom Spot 3].switch = off with a delay of 355ms
+10165ms ║RunTime Analysis CS > 21ms > PS > 10079ms > PE > 65ms > CE
+10166ms ║Piston waited at a semaphore for 10041ms
+10169ms ║Runtime (45647 bytes) successfully initialized in 10079ms (v0.3.109.20181207) (10167ms)
+10170ms ║╔Execution stage started
+10185ms ║║Condition #5 evaluated false (9ms)
+10186ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+10198ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+10200ms ║║Condition #12 evaluated false (11ms)
+10202ms ║║Condition group #8 evaluated false (state did not change) (12ms)
+10222ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+10225ms ║║Condition #18 evaluated false (19ms)
+10226ms ║║Condition group #14 evaluated false (state did not change) (22ms)
+10245ms ║║Comparison (enum) off changes_to (string) off = false (0ms)
+10247ms ║║Condition #26 evaluated false (18ms)
+10249ms ║║Condition group #23 evaluated false (state did not change) (19ms)
+10251ms ║╚Execution stage complete. (81ms)
+10253ms ║Setting up scheduled job for Wed, Jan 23 2019 @ 9:03:00 AM GMT (in 109.866s)
+10264ms ╚Event processed successfully (10264ms)
23/01/2019, 09:01:00 +162ms
+1ms ╔Received event [Bathroom Spot 1].switch = off with a delay of 356ms
+9665ms ║RunTime Analysis CS > 27ms > PS > 9567ms > PE > 72ms > CE
+9666ms ║Piston waited at a semaphore for 9518ms
+9669ms ║Runtime (45639 bytes) successfully initialized in 9567ms (v0.3.109.20181207) (9667ms)
+9670ms ║╔Execution stage started
+9684ms ║║Condition #5 evaluated false (8ms)
+9685ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+9698ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+9701ms ║║Condition #12 evaluated false (12ms)
+9702ms ║║Condition group #8 evaluated false (state did not change) (14ms)
+9724ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+9727ms ║║Condition #18 evaluated false (20ms)
+9729ms ║║Condition group #14 evaluated false (state did not change) (23ms)
+9761ms ║║Comparison (enum) off changes_to (string) off = false (1ms)
+9765ms ║║Cancelling condition #26’s schedules…
+9766ms ║║Condition #26 evaluated false (33ms)
+9767ms ║║Cancelling condition #23’s schedules…
+9768ms ║║Condition group #23 evaluated false (state changed) (36ms)
+9771ms ║╚Execution stage complete. (101ms)
+9773ms ║Setting up scheduled job for Wed, Jan 23 2019 @ 9:03:00 AM GMT (in 110.474s)
+9783ms ╚Event processed successfully (9783ms)
23/01/2019, 09:01:00 +232ms
+1ms ╔Received event [Bathroom Spot 2].switch = off with a delay of 377ms
+139ms ║RunTime Analysis CS > 20ms > PS > 55ms > PE > 63ms > CE
+141ms ║Runtime (45564 bytes) successfully initialized in 55ms (v0.3.109.20181207) (139ms)
+143ms ║╔Execution stage started
+158ms ║║Condition #5 evaluated false (9ms)
+159ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+172ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+175ms ║║Adding a timed trigger schedule for condition 12
+178ms ║║Cancelling condition #12’s schedules…
+180ms ║║Condition #12 evaluated false (16ms)
+181ms ║║Cancelling condition #8’s schedules…
+182ms ║║Condition group #8 evaluated false (state changed) (20ms)
+205ms ║║Comparison (enum) off changes_to (string) on = false (0ms)
+208ms ║║Condition #18 evaluated false (21ms)
+209ms ║║Condition group #14 evaluated false (state did not change) (24ms)
+227ms ║║Comparison (enum) off changes_to (string) off = true (1ms)
+230ms ║║Cancelling condition #26’s schedules…
+231ms ║║Condition #26 evaluated true (19ms)
+232ms ║║Cancelling condition #23’s schedules…
+233ms ║║Condition group #23 evaluated true (state changed) (21ms)
+236ms ║║Cancelling statement #24’s schedules…
+244ms ║║Executed virtual command setVariable (4ms)
+248ms ║╚Execution stage complete. (105ms)
+250ms ║Setting up scheduled job for Wed, Jan 23 2019 @ 9:03:00 AM GMT (in 119.927s)
+258ms ╚Event processed successfully (258ms)
23/01/2019, 09:00:59 +360ms
+1ms ╔Received event [Home].time = 1548234054578 with a delay of 4781ms
+559ms ║RunTime Analysis CS > 138ms > PS > 344ms > PE > 78ms > CE
+562ms ║Runtime (45568 bytes) successfully initialized in 344ms (v0.3.109.20181207) (560ms)
+564ms ║╔Execution stage started
+585ms ║║Cancelling condition #12’s schedules…
+586ms ║║Condition #12 evaluated true (2ms)
+594ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+596ms ║║Cancelling condition #13’s schedules…
+597ms ║║Condition #13 evaluated true (10ms)
+608ms ║║Comparison (enum) open is (string) open = true (2ms)
+611ms ║║Condition #40 evaluated true (13ms)
+613ms ║║Cancelling condition #8’s schedules…
+614ms ║║Condition group #8 evaluated true (state changed) (31ms)
+618ms ║║Cancelling statement #9’s schedules…
+647ms ║║Executed physical command [Bathroom Spot 1].off() (23ms)
+648ms ║║Executed [Bathroom Spot 1].off (26ms)
+672ms ║║Executed physical command [Bathroom Spot 2].off() (21ms)
+674ms ║║Executed [Bathroom Spot 2].off (23ms)
+699ms ║║Executed physical command [Bathroom Spot 3].off() (21ms)
+701ms ║║Executed [Bathroom Spot 3].off (24ms)
+725ms ║║Executed physical command [Bathroom Spot 4].off() (21ms)
+727ms ║║Executed [Bathroom Spot 4].off (24ms)
+758ms ║║Condition #18 evaluated false (24ms)
+760ms ║║Condition group #14 evaluated false (state did not change) (27ms)
+788ms ║║Condition #26 evaluated false (23ms)
+790ms ║║Condition group #23 evaluated false (state did not change) (25ms)
+794ms ║╚Execution stage complete. (231ms)
+796ms ╚Event processed successfully (796ms)
23/01/2019, 08:58:54 +428ms
+1ms ╔Received event [Bathroom Sensor].motion = inactive with a delay of 118ms
+118ms ║RunTime Analysis CS > 18ms > PS > 40ms > PE > 60ms > CE
+121ms ║Runtime (45569 bytes) successfully initialized in 40ms (v0.3.109.20181207) (118ms)
+122ms ║╔Execution stage started
+133ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+135ms ║║Condition #5 evaluated false (6ms)
+136ms ║║Condition group #1 evaluated false (state did not change) (8ms)
+146ms ║║Comparison (enum) inactive stays (string) inactive = true (2ms)
+149ms ║║Adding a timed trigger schedule for condition 12
+152ms ║║Condition #12 evaluated false (12ms)
+153ms ║║Condition group #8 evaluated false (state did not change) (14ms)
+177ms ║║Condition #18 evaluated false (20ms)
+178ms ║║Condition group #14 evaluated false (state did not change) (22ms)
+200ms ║║Condition #26 evaluated false (17ms)
+201ms ║║Condition group #23 evaluated false (state did not change) (20ms)
+204ms ║╚Execution stage complete. (82ms)
+206ms ║Setting up scheduled job for Wed, Jan 23 2019 @ 9:00:54 AM GMT (in 119.945s)
+214ms ╚Event processed successfully (213ms)
23/01/2019, 08:58:46 +88ms
+0ms ╔Received event [Home].time = 1548233926953 with a delay of -866ms
+207ms ║RunTime Analysis CS > 53ms > PS > 74ms > PE > 81ms > CE
+211ms ║Runtime (45562 bytes) successfully initialized in 74ms (v0.3.109.20181207) (209ms)
+214ms ║╔Execution stage started
+215ms ║╚Execution stage complete. (2ms)
+217ms ╚Event processed successfully (218ms)
23/01/2019, 08:58:21 +82ms
+1ms ╔Received event [Bathroom Spot 1].switch = on with a delay of 319ms
+9491ms ║RunTime Analysis CS > 19ms > PS > 9412ms > PE > 59ms > CE
+9492ms ║Piston waited at a semaphore for 9341ms
+9495ms ║Runtime (45635 bytes) successfully initialized in 9412ms (v0.3.109.20181207) (9492ms)
+9496ms ║╔Execution stage started
+9515ms ║║Condition #5 evaluated false (13ms)
+9517ms ║║Condition group #1 evaluated false (state did not change) (15ms)
+9529ms ║║Comparison (enum) active stays (string) inactive = false (2ms)
+9532ms ║║Cancelling any timed trigger schedules for condition 12
+9533ms ║║Cancelling statement #12’s schedules…
+9534ms ║║Condition #12 evaluated false (14ms)
+9535ms ║║Condition group #8 evaluated false (state did not change) (15ms)
+9555ms ║║Comparison (enum) on changes_to (string) on = false (1ms)
+9558ms ║║Cancelling condition #18’s schedules…
+9559ms ║║Condition #18 evaluated false (20ms)
+9561ms ║║Cancelling condition #14’s schedules…
+9562ms ║║Condition group #14 evaluated false (state changed) (24ms)
+9579ms ║║Comparison (enum) on changes_to (string) off = false (0ms)
+9582ms ║║Condition #26 evaluated false (16ms)
+9583ms ║║Condition group #23 evaluated false (state did not change) (18ms)
+9585ms ║╚Execution stage complete. (90ms)
+9587ms ╚Event processed successfully (9587ms)
23/01/2019, 08:58:21 +162ms
+1ms ╔Received event [Bathroom Spot 4].switch = on with a delay of 307ms
+154ms ║RunTime Analysis CS > 19ms > PS > 56ms > PE > 78ms > CE
+157ms ║Runtime (45572 bytes) successfully initialized in 56ms (v0.3.109.20181207) (154ms)
+158ms ║╔Execution stage started
+172ms ║║Condition #5 evaluated false (8ms)
+174ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+195ms ║║Comparison (enum) active stays (string) inactive = false (2ms)
+198ms ║║Cancelling any timed trigger schedules for condition 12
+199ms ║║Cancelling statement #12’s schedules…
+200ms ║║Condition #12 evaluated false (16ms)
+201ms ║║Condition group #8 evaluated false (state did not change) (17ms)
+222ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+225ms ║║Cancelling condition #18’s schedules…
+226ms ║║Condition #18 evaluated true (21ms)
+228ms ║║Cancelling condition #14’s schedules…
+229ms ║║Condition group #14 evaluated true (state changed) (24ms)
+240ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+242ms ║║Cancelling condition #30’s schedules…
+243ms ║║Condition #30 evaluated true (11ms)
+245ms ║║Cancelling condition #27’s schedules…
+246ms ║║Condition group #27 evaluated true (state changed) (14ms)
+249ms ║║Cancelling statement #28’s schedules…
+256ms ║║Executed virtual command setVariable (3ms)
+275ms ║║Comparison (enum) on changes_to (string) off = false (1ms)
+278ms ║║Cancelling condition #26’s schedules…
+279ms ║║Condition #26 evaluated false (18ms)
+281ms ║║Cancelling condition #23’s schedules…
+282ms ║║Condition group #23 evaluated false (state changed) (22ms)
+285ms ║╚Execution stage complete. (128ms)
+289ms ╚Event processed successfully (287ms)
23/01/2019, 08:58:20 +297ms
+1ms ╔Received event [Bathroom Sensor].motion = active with a delay of 146ms
+112ms ║RunTime Analysis CS > 17ms > PS > 38ms > PE > 58ms > CE
+115ms ║Runtime (45577 bytes) successfully initialized in 38ms (v0.3.109.20181207) (113ms)
+116ms ║╔Execution stage started
+126ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+128ms ║║Cancelling condition #5’s schedules…
+129ms ║║Condition #5 evaluated true (7ms)
+521ms ║║Comparison (enum) off is (string) off = true (2ms)
+524ms ║║Cancelling condition #6’s schedules…
+525ms ║║Condition #6 evaluated true (395ms)
+531ms ║║Comparison (string) :ccf413a3d2ef9ed766007dcbb2d3408d: is_not (string) :85be758d258a40390d4eeb1504b3b5c4: = true (3ms)
+533ms ║║Condition #39 evaluated true (6ms)
+534ms ║║Cancelling condition #1’s schedules…
+535ms ║║Condition group #1 evaluated true (state changed) (414ms)
+538ms ║║Cancelling statement #2’s schedules…
+550ms ║║Executed virtual command [Bathroom Spot 1, Bathroom Spot 2, Bathroom Spot 3, Bathroom Spot 4].setVariable (6ms)
+576ms ║║Executed physical command [Bathroom Spot 1].setLevel([100]) (21ms)
+577ms ║║Executed [Bathroom Spot 1].setLevel (24ms)
+597ms ║║Executed physical command [Bathroom Spot 2].setLevel([100]) (18ms)
+598ms ║║Executed [Bathroom Spot 2].setLevel (20ms)
+619ms ║║Executed physical command [Bathroom Spot 3].setLevel([100]) (18ms)
+620ms ║║Executed [Bathroom Spot 3].setLevel (20ms)
+641ms ║║Executed physical command [Bathroom Spot 4].setLevel([100]) (20ms)
+643ms ║║Executed [Bathroom Spot 4].setLevel (21ms)
+644ms ║║Skipping task 35 because of mode restrictions
+645ms ║║Skipping task 37 because of mode restrictions
+663ms ║║Executed physical command [Bathroom Spot 1].setColorTemperature([6410]) (14ms)
+665ms ║║Executed [Bathroom Spot 1].setColorTemperature (15ms)
+680ms ║║Executed physical command [Bathroom Spot 2].setColorTemperature([6410]) (14ms)
+681ms ║║Executed [Bathroom Spot 2].setColorTemperature (15ms)
+696ms ║║Executed physical command [Bathroom Spot 3].setColorTemperature([6410]) (13ms)
+697ms ║║Executed [Bathroom Spot 3].setColorTemperature (15ms)
+712ms ║║Executed physical command [Bathroom Spot 4].setColorTemperature([6410]) (13ms)
+713ms ║║Executed [Bathroom Spot 4].setColorTemperature (15ms)
+715ms ║║Skipping task 36 because of mode restrictions
+721ms ║║Skipped execution of physical command [Bathroom Spot 1].on([]) because it would make no change to the device. (3ms)
+722ms ║║Executed [Bathroom Spot 1].on (5ms)
+741ms ║║Executed physical command [Bathroom Spot 2].on() (17ms)
+742ms ║║Executed [Bathroom Spot 2].on (19ms)
+761ms ║║Executed physical command [Bathroom Spot 3].on() (17ms)
+762ms ║║Executed [Bathroom Spot 3].on (19ms)
+781ms ║║Executed physical command [Bathroom Spot 4].on() (17ms)
+783ms ║║Executed [Bathroom Spot 4].on (19ms)
+793ms ║║Comparison (enum) active stays (string) inactive = false (2ms)
+795ms ║║Cancelling any timed trigger schedules for condition 12
+796ms ║║Cancelling statement #12’s schedules…
+797ms ║║Condition #12 evaluated false (11ms)
+799ms ║║Condition group #8 evaluated false (state did not change) (12ms)
+820ms ║║Condition #18 evaluated false (18ms)
+821ms ║║Condition group #14 evaluated false (state did not change) (20ms)
+842ms ║║Cancelling condition #26’s schedules…
+843ms ║║Condition #26 evaluated false (18ms)
+845ms ║║Cancelling condition #23’s schedules…
+846ms ║║Condition group #23 evaluated false (state changed) (22ms)
+849ms ║╚Execution stage complete. (733ms)
+851ms ╚Event processed successfully (851ms)

[Bruce_Young]

What was the sequence of events you tried to initiate? I would think you would test it by giving it some motion and then moving out of range of the motion detector for 2 minutes to see if it turns off. At least at first I wouldn’t touch the switches. My understanding from your initial post was that is the problem - the lights don’t turn off after motion and switches are untouched.

Sequence in the trace seems to be:
8:58:20 Motion turns on lights
8:58:21 You turn on Spot 4 & Spot 1 (Is this a physical switch action or is the piston reacting to its own action?)
Note that the event labeled +1ms Recevied event [Bathroom Spot 1].switch = on waits for a semaphore for 9/5 seconds.
8:58:54 motion sensor goes inactive
9:00:59 Lights turn off (This is the proper action, correct?)
It then gets triggered 4 more times immediately to due to the switches changing(?) - These also wait for semaphore
9:02:59 Your 2 minute wait times out but nothing happens
9:44:34 you restart the piston
9:45:59 you hit “Test”(?) This starts the 2 minute inactive period for the motion sensor
9:47:58 2 minutes of no motion occurs and it executes the off command but it is skipped because they are already off

I am not seeing the lights left on after a timeout here. In fact the last trigger skips turning the lights off because they are already off.

I am very new to WebCore, so it is possible I am misinterpreting something, but please let me know what actions you believe occured.

[mastermc0]

I seem to have fixed it by removing the set of programmatic and just using viaMotion.