1) Give a description of the problem
I have several Cooper RFWC5 controllers for my Zwave setup. It is an in wall zwave scene controller with 5 buttons. I have each button set up with associations to turn on lights and combinations of lights. The RFWC5 has and indicator by each button. The indicator basically determines what command will be sent if the button is pushed. If the indicator is off the button will send and ON command. If the indicator on the button will send an OFF command. Normally this works quite nicely to control a light or relay. The problem starts when the light gets controlled by something else. Then the light and button are out of sync and a double press is required to get the desired response. The RFWC5 allows the indicators to be set externally. The DH uses an integer where each bit represents an indicator state. Send 0 and they are all off. Send 1 and the first one comes on…
The piston I created is to keep the indicators in sync with the state of each light.
The problem is that is frequently gets out of sync and I’m not able to figure out why. When I test it works and works well. Then it will just not do what it is supposed to do. I’ve added in a bit of logic to ensure it is not running multiple instances when the button is double or triple pushed. However, it still seems to randomly get it wrong. I feels to me like ST or WebCore is not getting the correct state of the light, or the timing is wrong.
2) What is the expected behaviour?
After piston execution the indicators should match the state each light/s.
3) What is happening/not happening?
Frequently (10-20%) of the time it is wrong. Seems to be more common on indicator 1. Not sure if that is because it is the most frequently used or if it is something in the program. I often find an indicator on when the light is off or off when light is on.
Looking for any input on what I may be missing, doing wrong, need to try.
4) Post a Green Snapshot of the piston
5) Attach logs after turning logging level to Full
2/20/2019, 8:15:48 AM +672ms
+0ms ╔Received event … = @BathLowerRunning with a delay of 60ms
+129ms ║RunTime Analysis CS > 19ms > PS > 39ms > PE > 72ms > CE
+132ms ║Runtime (45553 bytes) successfully initialized in 39ms (v0.3.110.20191009) (131ms)
+133ms ║╔Execution stage started
+141ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+143ms ║║Cancelling condition #85’s schedules…
+144ms ║║Condition #85 evaluated true (6ms)
+145ms ║║Cancelling condition #23’s schedules…
+146ms ║║Condition group #23 evaluated true (state changed) (9ms)
+272ms ║║Condition #77 evaluated false (124ms)
+278ms ║║Cancelling condition #79’s schedules…
+279ms ║║Condition #79 evaluated false (7ms)
+284ms ║║Condition #80 evaluated false (3ms)
+285ms ║║Cancelling condition #23’s schedules…
+285ms ║║Condition group #23 evaluated false (state changed) (138ms)
+292ms ║║Comparison (boolean) false stays (boolean) true = false (1ms)
+293ms ║║Cancelling any timed trigger schedules for condition 87
+294ms ║║Cancelling statement #87’s schedules…
+295ms ║║Condition #87 evaluated false (7ms)
+296ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+298ms ║╚Execution stage complete. (165ms)
+299ms ╚Event processed successfully (299ms)
12/20/2019, 8:15:48 AM +97ms
+0ms ╔Received event [SAAINS Home].time = 1576851349444 with a delay of -1348ms
+403ms ║RunTime Analysis CS > 162ms > PS > 176ms > PE > 65ms > CE
+406ms ║Runtime (45524 bytes) successfully initialized in 176ms (v0.3.110.20191009) (405ms)
+407ms ║╔Execution stage started
+415ms ║║Cancelling condition #23’s schedules…
+456ms ║║Cancelling condition #87’s schedules…
+457ms ║║Condition #87 evaluated true (2ms)
+459ms ║║Cancelling condition #86’s schedules…
+459ms ║║Condition group #86 evaluated true (state changed) (4ms)
+462ms ║║Cancelling statement #88’s schedules…
+467ms ║║Executed virtual command setVariable (2ms)
+470ms ║╚Execution stage complete. (63ms)
+471ms ╚Event processed successfully (471ms)
12/20/2019, 8:14:49 AM +287ms
+1ms ╔Received event …= @BathLowerRunning with a delay of 63ms
+133ms ║RunTime Analysis CS > 19ms > PS > 46ms > PE > 68ms > CE
+136ms ║Runtime (45552 bytes) successfully initialized in 46ms (v0.3.110.20191009) (135ms)
+137ms ║╔Execution stage started
+144ms ║║Comparison (boolean) true is (boolean) false = false (1ms)
+146ms ║║Cancelling condition #85’s schedules…
+147ms ║║Condition #85 evaluated false (6ms)
+148ms ║║Cancelling condition #23’s schedules…
+149ms ║║Condition group #23 evaluated false (state changed) (7ms)
+155ms ║║Comparison (boolean) true stays (boolean) true = true (1ms)
+157ms ║║Adding a timed trigger schedule for condition 87
+159ms ║║Condition #87 evaluated false (8ms)
+160ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+162ms ║╚Execution stage complete. (25ms)
+163ms ║Setting up scheduled job for Fri, Dec 20 2019 @ 8:15:49 AM CST (in 59.994s)
+175ms ╚Event processed successfully (175ms)
12/20/2019, 8:14:39 AM +387ms
+1ms ╔Received event [Bath Lower Control].button = pushed with a delay of 96ms
+9672ms ║RunTime Analysis CS > 18ms > PS > 9576ms > PE > 78ms > CE
+9673ms ║Piston waited at a semaphore for 9539ms
+9676ms ║Runtime (45597 bytes) successfully initialized in 9576ms (v0.3.110.20191009) (9674ms)
+9677ms ║╔Execution stage started
+9686ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+9687ms ║║Condition #85 evaluated true (5ms)
+9688ms ║║Condition group #23 evaluated true (state did not change) (6ms)
+9707ms ║║Cancelling condition #77’s schedules…
+9708ms ║║Condition #77 evaluated false (17ms)
+9712ms ║║Comparison (enum) pushed gets (string) pushed = true (0ms)
+9713ms ║║Condition #79 evaluated true (5ms)
+9714ms ║║Condition group #23 evaluated true (state did not change) (25ms)
+9716ms ║║Cancelling statement #81’s schedules…
+9720ms ║║Executed virtual command setVariable (1ms)
+9723ms ║║Executed virtual command setVariable (1ms)
+9726ms ║║Cancelling statement #52’s schedules…
+9741ms ║║Executed physical command [Bath Lower Fan].ping() (12ms)
+9742ms ║║Executed [Bath Lower Fan].ping (14ms)
+9755ms ║║Executed physical command [Bath Lower Heater].ping() (11ms)
+9756ms ║║Executed [Bath Lower Heater].ping (13ms)
+9769ms ║║Executed physical command [Bath Lower Light].ping() (11ms)
+9770ms ║║Executed [Bath Lower Light].ping (13ms)
+9782ms ║║Executed physical command [Bath Lower Vanity Light].ping() (11ms)
+9783ms ║║Executed [Bath Lower Vanity Light].ping (12ms)
+9786ms ║║Cancelling statement #57’s schedules…
+9789ms ║║Executed virtual command wait (0ms)
+9790ms ║║Requesting a wake up for Fri, Dec 20 2019 @ 8:14:49 AM CST (in 0.5s)
+9793ms ║╚Execution stage complete. (116ms)
+9795ms ║Setting up scheduled job for Fri, Dec 20 2019 @ 8:14:49 AM CST (in 1s)
+9803ms ╚Event processed successfully (9803ms)
12/20/2019, 8:14:39 AM +978ms
+1ms ╔Received event [Bath Lower Vanity Light].switch = off with a delay of 81ms
+116ms ║RunTime Analysis CS > 18ms > PS > 37ms > PE > 61ms > CE
+119ms ║Runtime (45523 bytes) successfully initialized in 37ms (v0.3.110.20191009) (117ms)
+120ms ║╔Execution stage started
+127ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+129ms ║║Condition #85 evaluated true (5ms)
+130ms ║║Condition group #23 evaluated true (state did not change) (6ms)
+143ms ║║Comparison (enum) off changes = true (0ms)
+145ms ║║Cancelling condition #77’s schedules…
+146ms ║║Condition #77 evaluated true (15ms)
+147ms ║║Condition group #23 evaluated true (state did not change) (17ms)
+149ms ║║Cancelling statement #81’s schedules…
+153ms ║║Executed virtual command setVariable (0ms)
+156ms ║║Executed virtual command setVariable (1ms)
+159ms ║║Cancelling statement #52’s schedules…
+186ms ║║Executed physical command [Bath Lower Fan].ping() (24ms)
+187ms ║║Executed [Bath Lower Fan].ping (26ms)
+200ms ║║Executed physical command [Bath Lower Heater].ping() (11ms)
+201ms ║║Executed [Bath Lower Heater].ping (13ms)
+214ms ║║Executed physical command [Bath Lower Light].ping() (11ms)
+215ms ║║Executed [Bath Lower Light].ping (13ms)
+229ms ║║Executed physical command [Bath Lower Vanity Light].ping() (12ms)
+230ms ║║Executed [Bath Lower Vanity Light].ping (14ms)
+233ms ║║Cancelling statement #57’s schedules…
+236ms ║║Executed virtual command wait (1ms)
+238ms ║║Waiting for 500ms
+745ms ║║Comparison (enum) off is (string) on = false (1ms)
+747ms ║║Cancelling condition #32’s schedules…
+748ms ║║Condition #32 evaluated false (6ms)
+749ms ║║Cancelling condition #27’s schedules…
+750ms ║║Condition group #27 evaluated false (state changed) (8ms)
+759ms ║║Comparison (enum) off is (string) on = false (2ms)
+760ms ║║Condition #38 evaluated false (8ms)
+761ms ║║Condition group #33 evaluated false (state did not change) (9ms)
+770ms ║║Comparison (enum) off is (string) on = false (2ms)
+771ms ║║Condition #44 evaluated false (7ms)
+772ms ║║Condition group #39 evaluated false (state did not change) (9ms)
+780ms ║║Comparison (enum) off is (string) on = false (2ms)
+781ms ║║Condition #72 evaluated false (6ms)
+782ms ║║Condition group #69 evaluated false (state did not change) (8ms)
+793ms ║║Comparison (enum) off is (string) on = false (1ms)
+795ms ║║Condition #50 evaluated false (10ms)
+796ms ║║Condition group #45 evaluated false (state did not change) (12ms)
+798ms ║║Cancelling statement #75’s schedules…
+1179ms ║║Executed physical command [Bath Lower Control].IndicatorAllSet([0]) (377ms)
+1180ms ║║Executed [Bath Lower Control].IndicatorAllSet (379ms)
+1183ms ║║Cancelling statement #83’s schedules…
+1187ms ║║Executed virtual command setVariable (1ms)
+1194ms ║║Comparison (boolean) false stays (boolean) true = false (2ms)
+1196ms ║║Cancelling any timed trigger schedules for condition 87
+1197ms ║║Cancelling statement #87’s schedules…
+1198ms ║║Condition #87 evaluated false (8ms)
+1199ms ║║Condition group #86 evaluated false (state did not change) (9ms)
+1201ms ║╚Execution stage complete. (1081ms)
+1202ms ╚Event processed successfully (1202ms)
12/20/2019, 8:14:38 AM +897ms
+0ms ╔Received event [Bath Lower Control].button = pushed with a delay of 154ms
+135ms ║RunTime Analysis CS > 26ms > PS > 37ms > PE > 73ms > CE
+138ms ║Runtime (45526 bytes) successfully initialized in 37ms (v0.3.110.20191009) (137ms)
+139ms ║╔Execution stage started
+148ms ║║Comparison (boolean) false is (boolean) false = true (2ms)
+150ms ║║Condition #85 evaluated true (5ms)
+151ms ║║Cancelling condition #23’s schedules…
+152ms ║║Condition group #23 evaluated true (state changed) (8ms)
+169ms ║║Condition #77 evaluated false (16ms)
+173ms ║║Comparison (enum) pushed gets (string) pushed = true (1ms)
+175ms ║║Cancelling condition #79’s schedules…
+176ms ║║Condition #79 evaluated true (6ms)
+177ms ║║Condition group #23 evaluated true (state did not change) (24ms)
+179ms ║║Cancelling statement #81’s schedules…
+183ms ║║Executed virtual command setVariable (1ms)
+187ms ║║Executed virtual command setVariable (1ms)
+190ms ║║Cancelling statement #52’s schedules…
+252ms ║║Executed physical command [Bath Lower Fan].ping() (59ms)
+253ms ║║Executed [Bath Lower Fan].ping (61ms)
+267ms ║║Executed physical command [Bath Lower Heater].ping() (11ms)
+267ms ║║Executed [Bath Lower Heater].ping (13ms)
+280ms ║║Executed physical command [Bath Lower Light].ping() (11ms)
+281ms ║║Executed [Bath Lower Light].ping (13ms)
+294ms ║║Executed physical command [Bath Lower Vanity Light].ping() (11ms)
+295ms ║║Executed [Bath Lower Vanity Light].ping (13ms)
+297ms ║║Cancelling statement #57’s schedules…
+300ms ║║Executed virtual command wait (1ms)
+301ms ║║Waiting for 500ms
+809ms ║║Comparison (enum) on is (string) on = true (1ms)
+810ms ║║Cancelling condition #32’s schedules…
+811ms ║║Condition #32 evaluated true (8ms)
+812ms ║║Cancelling condition #27’s schedules…
+813ms ║║Condition group #27 evaluated true (state changed) (10ms)
+815ms ║║Cancelling statement #63’s schedules…
+820ms ║║Calculating (integer) 0 + (integer) 1 >> (integer) 1
+823ms ║║Executed virtual command setVariable (1ms)
+832ms ║║Comparison (enum) off is (string) on = false (1ms)
+834ms ║║Condition #38 evaluated false (7ms)
+835ms ║║Condition group #33 evaluated false (state did not change) (8ms)
+842ms ║║Comparison (enum) off is (string) on = false (1ms)
+844ms ║║Condition #44 evaluated false (7ms)
+845ms ║║Condition group #39 evaluated false (state did not change) (7ms)
+852ms ║║Comparison (enum) off is (string) on = false (1ms)
+853ms ║║Condition #72 evaluated false (6ms)
+854ms ║║Condition group #69 evaluated false (state did not change) (7ms)
+867ms ║║Comparison (enum) off is (string) on = false (1ms)
+868ms ║║Condition #50 evaluated false (11ms)
+869ms ║║Condition group #45 evaluated false (state did not change) (12ms)
+872ms ║║Cancelling statement #75’s schedules…
+982ms ║║Executed physical command [Bath Lower Control].IndicatorAllSet([1]) (105ms)
+983ms ║║Executed [Bath Lower Control].IndicatorAllSet (107ms)
+985ms ║║Cancelling statement #83’s schedules…
+989ms ║║Executed virtual command setVariable (1ms)
+996ms ║║Comparison (boolean) false stays (boolean) true = false (1ms)
+998ms ║║Cancelling any timed trigger schedules for condition 87
+999ms ║║Cancelling statement #87’s schedules…
+1000ms ║║Condition #87 evaluated false (7ms)
+1001ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+1002ms ║╚Execution stage complete. (863ms)
+1003ms ╚Event processed successfully (1004ms)
12/20/2019, 8:14:28 AM +205ms
+1ms ╔Received event [Bath Lower Vanity Light].switch = on with a delay of 87ms
+9396ms ║RunTime Analysis CS > 20ms > PS > 9309ms > PE > 66ms > CE
+9397ms ║Piston waited at a semaphore for 9264ms
+9399ms ║Runtime (45598 bytes) successfully initialized in 9309ms (v0.3.110.20191009) (9397ms)
+9400ms ║╔Execution stage started
+9408ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+9409ms ║║Condition #85 evaluated true (5ms)
+9410ms ║║Condition group #23 evaluated true (state did not change) (6ms)
+9424ms ║║Comparison (enum) on changes = false (0ms)
+9426ms ║║Condition #77 evaluated false (15ms)
+9432ms ║║Cancelling condition #79’s schedules…
+9433ms ║║Condition #79 evaluated false (6ms)
+9438ms ║║Condition #80 evaluated false (4ms)
+9439ms ║║Cancelling condition #23’s schedules…
+9440ms ║║Condition group #23 evaluated false (state changed) (29ms)
+9446ms ║║Comparison (boolean) false stays (boolean) true = false (2ms)
+9448ms ║║Cancelling any timed trigger schedules for condition 87
+9449ms ║║Cancelling statement #87’s schedules…
+9450ms ║║Condition #87 evaluated false (7ms)
+9451ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+9452ms ║╚Execution stage complete. (52ms)
+9453ms ╚Event processed successfully (9453ms)
12/20/2019, 8:14:27 AM +338ms
+1ms ╔Received event [Bath Lower Control].button = pushed with a delay of 93ms
+127ms ║RunTime Analysis CS > 20ms > PS > 50ms > PE > 57ms > CE
+130ms ║Runtime (45521 bytes) successfully initialized in 50ms (v0.3.110.20191009) (128ms)
+131ms ║╔Execution stage started
+138ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+139ms ║║Condition #85 evaluated true (4ms)
+140ms ║║Condition group #23 evaluated true (state did not change) (6ms)
+157ms ║║Condition #77 evaluated false (16ms)
+161ms ║║Comparison (enum) pushed gets (string) pushed = true (1ms)
+162ms ║║Condition #79 evaluated true (4ms)
+163ms ║║Condition group #23 evaluated true (state did not change) (22ms)
+165ms ║║Cancelling statement #81’s schedules…
+169ms ║║Executed virtual command setVariable (0ms)
+172ms ║║Executed virtual command setVariable (1ms)
+174ms ║║Cancelling statement #52’s schedules…
+248ms ║║Executed physical command [Bath Lower Fan].ping() (71ms)
+249ms ║║Executed [Bath Lower Fan].ping (73ms)
+266ms ║║Executed physical command [Bath Lower Heater].ping() (15ms)
+267ms ║║Executed [Bath Lower Heater].ping (16ms)
+281ms ║║Executed physical command [Bath Lower Light].ping() (13ms)
+282ms ║║Executed [Bath Lower Light].ping (15ms)
+296ms ║║Executed physical command [Bath Lower Vanity Light].ping() (13ms)
+297ms ║║Executed [Bath Lower Vanity Light].ping (14ms)
+300ms ║║Cancelling statement #57’s schedules…
+303ms ║║Executed virtual command wait (0ms)
+304ms ║║Waiting for 500ms
+812ms ║║Comparison (enum) off is (string) on = false (1ms)
+814ms ║║Condition #32 evaluated false (8ms)
+815ms ║║Condition group #27 evaluated false (state did not change) (9ms)
+822ms ║║Comparison (enum) off is (string) on = false (1ms)
+824ms ║║Condition #38 evaluated false (7ms)
+825ms ║║Condition group #33 evaluated false (state did not change) (8ms)
+833ms ║║Comparison (enum) off is (string) on = false (2ms)
+834ms ║║Condition #44 evaluated false (7ms)
+835ms ║║Condition group #39 evaluated false (state did not change) (8ms)
+843ms ║║Comparison (enum) off is (string) on = false (2ms)
+844ms ║║Condition #72 evaluated false (6ms)
+845ms ║║Condition group #69 evaluated false (state did not change) (8ms)
+858ms ║║Comparison (enum) off is (string) on = false (2ms)
+860ms ║║Condition #50 evaluated false (12ms)
+861ms ║║Condition group #45 evaluated false (state did not change) (13ms)
+863ms ║║Cancelling statement #75’s schedules…
+969ms ║║Executed physical command [Bath Lower Control].IndicatorAllSet([0]) (102ms)
+970ms ║║Executed [Bath Lower Control].IndicatorAllSet (104ms)
+973ms ║║Cancelling statement #83’s schedules…
+976ms ║║Executed virtual command setVariable (1ms)
+983ms ║║Comparison (boolean) false stays (boolean) true = false (2ms)
+985ms ║║Cancelling any timed trigger schedules for condition 87
+985ms ║║Cancelling statement #87’s schedules…
+986ms ║║Condition #87 evaluated false (7ms)
+987ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+989ms ║╚Execution stage complete. (859ms)
+990ms ╚Event processed successfully (990ms)
12/20/2019, 8:14:25 AM +2ms
+1ms ╔Received event [Bath Lower Control].button = pushed with a delay of 87ms
+138ms ║RunTime Analysis CS > 19ms > PS > 61ms > PE > 57ms > CE
+141ms ║Runtime (45518 bytes) successfully initialized in 61ms (v0.3.110.20191009) (138ms)
+142ms ║╔Execution stage started
+150ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+151ms ║║Condition #85 evaluated true (5ms)
+152ms ║║Cancelling condition #23’s schedules…
+153ms ║║Condition group #23 evaluated true (state changed) (7ms)
+170ms ║║Condition #77 evaluated false (16ms)
+174ms ║║Comparison (enum) pushed gets (string) pushed = true (1ms)
+176ms ║║Cancelling condition #79’s schedules…
+177ms ║║Condition #79 evaluated true (5ms)
+178ms ║║Condition group #23 evaluated true (state did not change) (23ms)
+180ms ║║Cancelling statement #81’s schedules…
+183ms ║║Executed virtual command setVariable (1ms)
+187ms ║║Executed virtual command setVariable (1ms)
+190ms ║║Cancelling statement #52’s schedules…
+208ms ║║Executed physical command [Bath Lower Fan].ping() (14ms)
+209ms ║║Executed [Bath Lower Fan].ping (16ms)
+222ms ║║Executed physical command [Bath Lower Heater].ping() (12ms)
+223ms ║║Executed [Bath Lower Heater].ping (14ms)
+237ms ║║Executed physical command [Bath Lower Light].ping() (11ms)
+237ms ║║Executed [Bath Lower Light].ping (13ms)
+251ms ║║Executed physical command [Bath Lower Vanity Light].ping() (12ms)
+252ms ║║Executed [Bath Lower Vanity Light].ping (13ms)
+254ms ║║Cancelling statement #57’s schedules…
+258ms ║║Executed virtual command wait (0ms)
+258ms ║║Waiting for 500ms
+767ms ║║Comparison (enum) off is (string) on = false (2ms)
+769ms ║║Cancelling condition #32’s schedules…
+770ms ║║Condition #32 evaluated false (8ms)
+771ms ║║Cancelling condition #27’s schedules…
+771ms ║║Condition group #27 evaluated false (state changed) (10ms)
+779ms ║║Comparison (enum) off is (string) on = false (1ms)
+781ms ║║Condition #38 evaluated false (6ms)
+782ms ║║Condition group #33 evaluated false (state did not change) (7ms)
+790ms ║║Comparison (enum) off is (string) on = false (1ms)
+792ms ║║Condition #44 evaluated false (7ms)
+792ms ║║Condition group #39 evaluated false (state did not change) (8ms)
+801ms ║║Comparison (enum) off is (string) on = false (2ms)
+802ms ║║Condition #72 evaluated false (7ms)
+803ms ║║Condition group #69 evaluated false (state did not change) (8ms)
+817ms ║║Comparison (enum) off is (string) on = false (2ms)
+819ms ║║Condition #50 evaluated false (12ms)
+820ms ║║Condition group #45 evaluated false (state did not change) (14ms)
+822ms ║║Cancelling statement #75’s schedules…
+846ms ║║Executed physical command [Bath Lower Control].IndicatorAllSet([0]) (19ms)
+847ms ║║Executed [Bath Lower Control].IndicatorAllSet (21ms)
+849ms ║║Cancelling statement #83’s schedules…
+853ms ║║Executed virtual command setVariable (1ms)
+859ms ║║Comparison (boolean) false stays (boolean) true = false (1ms)
+861ms ║║Cancelling any timed trigger schedules for condition 87
+862ms ║║Cancelling statement #87’s schedules…
+863ms ║║Condition #87 evaluated false (7ms)
+863ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+865ms ║╚Execution stage complete. (724ms)
+867ms ╚Event processed successfully (866ms)
12/20/2019, 8:10:47 AM +761ms
+1ms ╔Received event…= @BathLowerRunning with a delay of 64ms
+122ms ║RunTime Analysis CS > 18ms > PS > 42ms > PE > 62ms > CE
+125ms ║Runtime (45544 bytes) successfully initialized in 42ms (v0.3.110.20191009) (124ms)
+126ms ║╔Execution stage started
+223ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+224ms ║║Cancelling condition #85’s schedules…
+225ms ║║Condition #85 evaluated true (95ms)
+226ms ║║Condition group #23 evaluated true (state did not change) (96ms)
+243ms ║║Cancelling condition #77’s schedules…
+244ms ║║Condition #77 evaluated false (17ms)
+250ms ║║Cancelling condition #79’s schedules…
+251ms ║║Condition #79 evaluated false (6ms)
+256ms ║║Condition #80 evaluated false (4ms)
+257ms ║║Cancelling condition #23’s schedules…
+257ms ║║Condition group #23 evaluated false (state changed) (30ms)
+263ms ║║Comparison (boolean) false stays (boolean) true = false (1ms)
+265ms ║║Cancelling any timed trigger schedules for condition 87
+266ms ║║Cancelling statement #87’s schedules…
+267ms ║║Cancelling condition #87’s schedules…
+268ms ║║Condition #87 evaluated false (7ms)
+268ms ║║Cancelling condition #86’s schedules…
+269ms ║║Condition group #86 evaluated false (state changed) (10ms)
+271ms ║╚Execution stage complete. (145ms)
+272ms ╚Event processed successfully (272ms)
12/20/2019, 8:10:47 AM +39ms
+0ms ╔Received event…time = 1576851040036 with a delay of 7002ms
+558ms ║RunTime Analysis CS > 229ms > PS > 271ms > PE > 59ms > CE
+561ms ║Runtime (45520 bytes) successfully initialized in 271ms (v0.3.110.20191009) (560ms)
+562ms ║╔Execution stage started
+570ms ║║Cancelling condition #23’s schedules…
+604ms ║║Cancelling condition #87’s schedules…
+605ms ║║Condition #87 evaluated true (2ms)
+606ms ║║Cancelling condition #86’s schedules…
+607ms ║║Condition group #86 evaluated true (state changed) (5ms)
+610ms ║║Cancelling statement #88’s schedules…
+615ms ║║Executed virtual command setVariable (1ms)
+617ms ║╚Execution stage complete. (55ms)
+618ms ╚Event processed successfully (619ms)
12/20/2019, 8:09:39 AM +888ms
+0ms ╔Received event [SAAINS Home].:de078d7ee8065d88dd14ecaf1ff0f7be: = @BathLowerRunning with a delay of 62ms
+125ms ║RunTime Analysis CS > 20ms > PS > 43ms > PE > 63ms > CE
+128ms ║Runtime (45549 bytes) successfully initialized in 43ms (v0.3.110.20191009) (127ms)
+129ms ║╔Execution stage started
+136ms ║║Comparison (boolean) true is (boolean) false = false (2ms)
+137ms ║║Cancelling condition #85’s schedules…
+138ms ║║Condition #85 evaluated false (5ms)
+139ms ║║Cancelling condition #23’s schedules…
+140ms ║║Condition group #23 evaluated false (state changed) (8ms)
+146ms ║║Comparison (boolean) true stays (boolean) true = true (1ms)
+147ms ║║Adding a timed trigger schedule for condition 87
+149ms ║║Condition #87 evaluated false (7ms)
+150ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+153ms ║╚Execution stage complete. (24ms)
+154ms ║Setting up scheduled job for Fri, Dec 20 2019 @ 8:10:40 AM CST (in 59.995s)
+166ms ╚Event processed successfully (167ms)
12/20/2019, 8:09:30 AM +234ms
+0ms ╔Received event [Bath Lower Vanity Light].switch = off with a delay of 76ms
+9435ms ║RunTime Analysis CS > 19ms > PS > 9353ms > PE > 63ms > CE
+9436ms ║Piston waited at a semaphore for 9307ms
+9438ms ║Runtime (45594 bytes) successfully initialized in 9353ms (v0.3.110.20191009) (9437ms)
+9439ms ║╔Execution stage started
+9446ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+9448ms ║║Condition #85 evaluated true (4ms)
+9448ms ║║Condition group #23 evaluated true (state did not change) (5ms)
+9463ms ║║Comparison (enum) off changes = true (1ms)
+9465ms ║║Cancelling condition #77’s schedules…
+9466ms ║║Condition #77 evaluated true (16ms)
+9467ms ║║Condition group #23 evaluated true (state did not change) (17ms)
+9469ms ║║Cancelling statement #81’s schedules…
+9472ms ║║Executed virtual command setVariable (1ms)
+9475ms ║║Executed virtual command setVariable (1ms)
+9478ms ║║Cancelling statement #52’s schedules…
+9493ms ║║Executed physical command [Bath Lower Fan].ping() (12ms)
+9494ms ║║Executed [Bath Lower Fan].ping (14ms)
+9507ms ║║Executed physical command [Bath Lower Heater].ping() (11ms)
+9508ms ║║Executed [Bath Lower Heater].ping (12ms)
+9520ms ║║Executed physical command [Bath Lower Light].ping() (11ms)
+9521ms ║║Executed [Bath Lower Light].ping (13ms)
+9534ms ║║Executed physical command [Bath Lower Vanity Light].ping() (10ms)
+9534ms ║║Executed [Bath Lower Vanity Light].ping (12ms)
+9537ms ║║Cancelling statement #57’s schedules…
+9540ms ║║Executed virtual command wait (1ms)
+9541ms ║║Requesting a wake up for Fri, Dec 20 2019 @ 8:09:40 AM CST (in 0.5s)
+9544ms ║╚Execution stage complete. (105ms)
+9546ms ║Setting up scheduled job for Fri, Dec 20 2019 @ 8:09:40 AM CST (in 1s)
+9556ms ╚Event processed successfully (9556ms)
12/20/2019, 8:09:29 AM +291ms
+1ms ╔Received event [Bath Lower Control].button = pushed with a delay of 775ms
+116ms ║RunTime Analysis CS > 19ms > PS > 38ms > PE > 59ms > CE
+119ms ║Runtime (45520 bytes) successfully initialized in 38ms (v0.3.110.20191009) (116ms)
+120ms ║╔Execution stage started
+127ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+128ms ║║Condition #85 evaluated true (4ms)
+129ms ║║Cancelling condition #23’s schedules…
+130ms ║║Condition group #23 evaluated true (state changed) (7ms)
+146ms ║║Condition #77 evaluated false (15ms)
+150ms ║║Comparison (enum) pushed gets (string) pushed = true (1ms)
+151ms ║║Cancelling condition #79’s schedules…
+152ms ║║Condition #79 evaluated true (5ms)
+153ms ║║Condition group #23 evaluated true (state did not change) (22ms)
+155ms ║║Cancelling statement #81’s schedules…
+158ms ║║Executed virtual command setVariable (1ms)
+162ms ║║Executed virtual command setVariable (0ms)
+164ms ║║Cancelling statement #52’s schedules…
+230ms ║║Executed physical command [Bath Lower Fan].ping() (63ms)
+231ms ║║Executed [Bath Lower Fan].ping (65ms)
+246ms ║║Executed physical command [Bath Lower Heater].ping() (12ms)
+247ms ║║Executed [Bath Lower Heater].ping (14ms)
+261ms ║║Executed physical command [Bath Lower Light].ping() (13ms)
+262ms ║║Executed [Bath Lower Light].ping (14ms)
+275ms ║║Executed physical command [Bath Lower Vanity Light].ping() (12ms)
+276ms ║║Executed [Bath Lower Vanity Light].ping (14ms)
+278ms ║║Cancelling statement #57’s schedules…
+281ms ║║Executed virtual command wait (0ms)
+282ms ║║Waiting for 500ms
+790ms ║║Comparison (enum) on is (string) on = true (1ms)
+792ms ║║Cancelling condition #32’s schedules…
+793ms ║║Condition #32 evaluated true (8ms)
+794ms ║║Cancelling condition #27’s schedules…
+795ms ║║Condition group #27 evaluated true (state changed) (10ms)
+797ms ║║Cancelling statement #63’s schedules…
+801ms ║║Calculating (integer) 0 + (integer) 1 >> (integer) 1
+804ms ║║Executed virtual command setVariable (1ms)
+813ms ║║Comparison (enum) off is (string) on = false (2ms)
+814ms ║║Condition #38 evaluated false (7ms)
+815ms ║║Condition group #33 evaluated false (state did not change) (8ms)
+823ms ║║Comparison (enum) off is (string) on = false (2ms)
+824ms ║║Condition #44 evaluated false (7ms)
+825ms ║║Condition group #39 evaluated false (state did not change) (8ms)
+834ms ║║Comparison (enum) off is (string) on = false (1ms)
+835ms ║║Condition #72 evaluated false (8ms)
+836ms ║║Condition group #69 evaluated false (state did not change) (9ms)
+849ms ║║Comparison (enum) off is (string) on = false (2ms)
+851ms ║║Condition #50 evaluated false (12ms)
+852ms ║║Condition group #45 evaluated false (state did not change) (13ms)
+854ms ║║Cancelling statement #75’s schedules…
+971ms ║║Executed physical command [Bath Lower Control].IndicatorAllSet([1]) (112ms)
+971ms ║║Executed [Bath Lower Control].IndicatorAllSet (114ms)
+974ms ║║Cancelling statement #83’s schedules…
+977ms ║║Executed virtual command setVariable (1ms)
+984ms ║║Comparison (boolean) false stays (boolean) true = false (2ms)
+986ms ║║Cancelling any timed trigger schedules for condition 87
+986ms ║║Cancelling statement #87’s schedules…
+987ms ║║Condition #87 evaluated false (7ms)
+988ms ║║Condition group #86 evaluated false (state did not change) (8ms)
+990ms ║╚Execution stage complete. (871ms)
+991ms ╚Event processed successfully (991ms)
12/20/2019, 7:54:17 AM +540ms
+1ms ╔Received event… = @BathLowerRunning with a delay of 67ms
+130ms ║RunTime Analysis CS > 23ms > PS > 43ms > PE > 63ms > CE
+132ms ║Runtime (45545 bytes) successfully initialized in 43ms (v0.3.110.20191009) (130ms)
+133ms ║╔Execution stage started
+141ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+142ms ║║Cancelling condition #85’s schedules…
+143ms ║║Condition #85 evaluated true (6ms)
+144ms ║║Condition group #23 evaluated true (state did not change) (7ms)
+163ms ║║Cancelling condition #77’s schedules…
+164ms ║║Condition #77 evaluated false (18ms)
+170ms ║║Cancelling condition #79’s schedules…
+171ms ║║Condition #79 evaluated false (7ms)
+176ms ║║Condition #80 evaluated false (4ms)
+177ms ║║Cancelling condition #23’s schedules…