Inconsistent execution of multi contacts to change thermostat program

tange1 · 2019-09-18 14:54:17 UTC

1) Give a description of the problem
I have a piston that most of the time works as intended but sometimes i find my thermostats in “doors open” when all doors are closed implying the piston did not work?

2) What is the expected behavior?
If all contact sensors are closed, 3 thermostats should be set to program “doors closed”. If anyone one sensor is open, set the thermostats program to doors open.

3) What is happening/not happening?
Currently all contacts are closed but the thermostat is showing program “doors open”.

**4) Post a Green Snapshot of the piston

5) Attach logs after turning logging level to Full
9/18/2019, 10:38:38 AM +137ms
+1ms ╔Received event [My home].time/recovery = 1568817518132 with a delay of 5ms
+121ms ║RunTime Analysis CS > 21ms > PS > 33ms > PE > 67ms > CE
+124ms ║Runtime (39900 bytes) successfully initialized in 33ms (v0.3.10e.20190628) (122ms)
+125ms ║╔Execution stage started
+126ms ║╚Execution stage complete. (1ms)
+127ms ╚Event processed successfully (127ms)
9/18/2019, 10:37:38 AM +794ms
+1ms ╔Received event [My home].time/recovery = 1568817458790 with a delay of 4ms
+176ms ║RunTime Analysis CS > 47ms > PS > 73ms > PE > 56ms > CE
+179ms ║Runtime (39900 bytes) successfully initialized in 73ms (v0.3.10e.20190628) (176ms)
+180ms ║╔Execution stage started
+180ms ║╚Execution stage complete. (1ms)
+182ms ╚Event processed successfully (181ms)
9/18/2019, 10:36:52 AM +465ms
+0ms ╔Received event [My home].time/recovery = 1568817412461 with a delay of 3ms
+115ms ║RunTime Analysis CS > 22ms > PS > 40ms > PE > 53ms > CE
+117ms ║Runtime (39900 bytes) successfully initialized in 40ms (v0.3.10e.20190628) (116ms)
+118ms ║╔Execution stage started
+119ms ║╚Execution stage complete. (1ms)
+121ms ╚Event processed successfully (120ms)
9/18/2019, 10:34:29 AM +171ms
+0ms ╔Received event [My home].time/recovery = 1568817269165 with a delay of 6ms
+153ms ║RunTime Analysis CS > 36ms > PS > 63ms > PE > 53ms > CE
+157ms ║Runtime (39900 bytes) successfully initialized in 63ms (v0.3.10e.20190628) (156ms)
+158ms ║╔Execution stage started
+160ms ║╚Execution stage complete. (2ms)
+161ms ╚Event processed successfully (161ms)
9/18/2019, 7:31:17 AM +153ms
+1ms ╔Received event [My home].time/recovery = 1568806277149 with a delay of 4ms
+116ms ║RunTime Analysis CS > 21ms > PS > 41ms > PE > 54ms > CE
+119ms ║Runtime (39900 bytes) successfully initialized in 41ms (v0.3.10e.20190628) (117ms)
+120ms ║╔Execution stage started
+120ms ║╚Execution stage complete. (1ms)
+122ms ╚Event processed successfully (121ms)
9/18/2019, 7:31:06 AM +157ms
+1ms ╔Received event [My home].time/recovery = 1568806266152 with a delay of 5ms
+119ms ║RunTime Analysis CS > 23ms > PS > 44ms > PE > 51ms > CE
+121ms ║Runtime (39900 bytes) successfully initialized in 44ms (v0.3.10e.20190628) (120ms)
+122ms ║╔Execution stage started
+123ms ║╚Execution stage complete. (1ms)
+124ms ╚Event processed successfully (124ms)
9/18/2019, 7:24:39 AM +172ms
+1ms ╔Received event [My home].time/recovery = 1568805879168 with a delay of 4ms
+125ms ║RunTime Analysis CS > 32ms > PS > 39ms > PE > 53ms > CE
+127ms ║Runtime (39900 bytes) successfully initialized in 39ms (v0.3.10e.20190628) (126ms)
+128ms ║╔Execution stage started
+129ms ║╚Execution stage complete. (1ms)
+130ms ╚Event processed successfully (130ms)
9/18/2019, 7:24:22 AM +183ms
+1ms ╔Received event [My home].time/recovery = 1568805862178 with a delay of 5ms
+2740ms ║RunTime Analysis CS > 32ms > PS > 2313ms > PE > 395ms > CE
+2741ms ║Piston waited at a semaphore for 2255ms
+2744ms ║Runtime (39975 bytes) successfully initialized in 2313ms (v0.3.10e.20190628) (2742ms)
+2745ms ║╔Execution stage started
+2745ms ║╚Execution stage complete. (1ms)
+2747ms ╚Event processed successfully (2746ms)
9/18/2019, 7:21:28 AM +201ms
+1ms ╔Received event [My home].time/recovery = 1568805688197 with a delay of 4ms
+163ms ║RunTime Analysis CS > 32ms > PS > 68ms > PE > 63ms > CE
+166ms ║Runtime (39900 bytes) successfully initialized in 68ms (v0.3.10e.20190628) (165ms)
+167ms ║╔Execution stage started
+168ms ║╚Execution stage complete. (1ms)
+169ms ╚Event processed successfully (169ms)
9/18/2019, 7:15:41 AM +117ms
+2ms ╔Received event [Rear Bay 2].contact = open with a delay of 125ms
+133ms ║RunTime Analysis CS > 35ms > PS > 46ms > PE > 51ms > CE
+135ms ║Runtime (39887 bytes) successfully initialized in 46ms (v0.3.10e.20190628) (133ms)
+136ms ║╔Execution stage started
+193ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+195ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+197ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+199ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+202ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+204ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+206ms ║║Comparison (enum) open is (string) closed = false (1ms)
+209ms ║║Cancelling condition #2’s schedules…
+210ms ║║Condition #2 evaluated false (69ms)
+211ms ║║Cancelling condition #1’s schedules…
+212ms ║║Condition group #1 evaluated false (state changed) (72ms)
+214ms ║║Cancelling statement #3’s schedules…
+5576ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (5352ms)
+5577ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (5354ms)
+5980ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (398ms)
+5981ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (400ms)
+8454ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (2466ms)
+8455ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (2468ms)
+8457ms ║╚Execution stage complete. (8321ms)
+8458ms ╚Event processed successfully (8458ms)
9/18/2019, 6:23:46 AM +147ms
+0ms ╔Received event [My home].time/recovery = 1568802226142 with a delay of 5ms
+99ms ║RunTime Analysis CS > 19ms > PS > 32ms > PE > 48ms > CE
+102ms ║Runtime (39896 bytes) successfully initialized in 32ms (v0.3.10e.20190628) (100ms)
+103ms ║╔Execution stage started
+103ms ║╚Execution stage complete. (1ms)
+105ms ╚Event processed successfully (104ms)
9/18/2019, 6:22:44 AM +128ms
+0ms ╔Received event [My home].time/recovery = 1568802164124 with a delay of 4ms
+242ms ║RunTime Analysis CS > 46ms > PS > 51ms > PE > 145ms > CE
+245ms ║Runtime (39898 bytes) successfully initialized in 51ms (v0.3.10e.20190628) (244ms)
+246ms ║╔Execution stage started
+247ms ║╚Execution stage complete. (1ms)
+248ms ╚Event processed successfully (247ms)
9/18/2019, 6:00:28 AM +685ms
+2ms ╔Received event [Rear Bay 5].contact = closed with a delay of 134ms
+127ms ║RunTime Analysis CS > 29ms > PS > 46ms > PE > 51ms > CE
+129ms ║Runtime (39892 bytes) successfully initialized in 46ms (v0.3.10e.20190628) (127ms)
+130ms ║╔Execution stage started
+179ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+181ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+183ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+185ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+187ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+190ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+192ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+194ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+196ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+198ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+200ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+203ms ║║Cancelling condition #2’s schedules…
+204ms ║║Condition #2 evaluated true (70ms)
+205ms ║║Cancelling condition #1’s schedules…
+206ms ║║Condition group #1 evaluated true (state changed) (72ms)
+208ms ║║Cancelling statement #5’s schedules…
+3357ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Closed]) (3139ms)
+3358ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (3141ms)
+6291ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Closed]) (2927ms)
+6292ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (2929ms)
+9095ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Closed]) (2798ms)
+9096ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (2799ms)
+9098ms ║╚Execution stage complete. (8968ms)
+9099ms ╚Event processed successfully (9099ms)
9/18/2019, 6:00:09 AM +792ms
+1ms ╔Received event [Rear Bay 5].contact = open with a delay of 84ms
+102ms ║RunTime Analysis CS > 25ms > PS > 30ms > PE > 47ms > CE
+105ms ║Runtime (39886 bytes) successfully initialized in 30ms (v0.3.10e.20190628) (102ms)
+106ms ║╔Execution stage started
+151ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+153ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+155ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+157ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+159ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+161ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+163ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+165ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+167ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+169ms ║║Comparison (enum) open is (string) closed = false (1ms)
+172ms ║║Cancelling condition #2’s schedules…
+173ms ║║Condition #2 evaluated false (64ms)
+174ms ║║Cancelling condition #1’s schedules…
+175ms ║║Condition group #1 evaluated false (state changed) (65ms)
+177ms ║║Cancelling statement #3’s schedules…
+5350ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (5165ms)
+5351ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (5168ms)
+7937ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (2581ms)
+7938ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (2583ms)
+10218ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (2274ms)
+10219ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (2276ms)
+10221ms ║╚Execution stage complete. (10116ms)
+10222ms ╚Event processed successfully (10222ms)
9/18/2019, 5:28:20 AM +212ms
+0ms ╔Received event [My home].time/recovery = 1568798900205 with a delay of 6ms
+8066ms ║RunTime Analysis CS > 57ms > PS > 7954ms > PE > 55ms > CE
+8067ms ║Piston waited at a semaphore for 7888ms
+8069ms ║Runtime (39971 bytes) successfully initialized in 7954ms (v0.3.10e.20190628) (8068ms)
+8070ms ║╔Execution stage started
+8071ms ║╚Execution stage complete. (1ms)
+8072ms ╚Event processed successfully (8072ms)
9/18/2019, 5:28:18 AM +87ms
+1ms ╔Received event [Front Bay 3].contact = closed with a delay of 105ms
+121ms ║RunTime Analysis CS > 23ms > PS > 48ms > PE > 50ms > CE
+124ms ║Runtime (39890 bytes) successfully initialized in 48ms (v0.3.10e.20190628) (122ms)
+125ms ║╔Execution stage started
+171ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+173ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+175ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+177ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+179ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+181ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+184ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+186ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+188ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+190ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+193ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+196ms ║║Condition #2 evaluated true (66ms)
+197ms ║║Condition group #1 evaluated true (state did not change) (67ms)
+199ms ║║Cancelling statement #5’s schedules…
+3636ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Closed]) (3430ms)
+3637ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (3432ms)
+4007ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Closed]) (365ms)
+4008ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (367ms)
+4759ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Closed]) (745ms)
+4760ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (747ms)
+4762ms ║╚Execution stage complete. (4637ms)
+4763ms ╚Event processed successfully (4763ms)
9/18/2019, 1:00:42 AM +444ms
+1ms ╔Received event [Front Bay 3].contact = closed with a delay of 148ms
+129ms ║RunTime Analysis CS > 28ms > PS > 48ms > PE > 54ms > CE
+132ms ║Runtime (39893 bytes) successfully initialized in 48ms (v0.3.10e.20190628) (130ms)
+133ms ║╔Execution stage started
+182ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+184ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+186ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+188ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+190ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+192ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+194ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+196ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+198ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+200ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+202ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+205ms ║║Cancelling condition #2’s schedules…
+206ms ║║Condition #2 evaluated true (68ms)
+207ms ║║Cancelling condition #1’s schedules…
+207ms ║║Condition group #1 evaluated true (state changed) (71ms)
+209ms ║║Cancelling statement #5’s schedules…
+3474ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Closed]) (3257ms)
+3476ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (3259ms)
+6007ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Closed]) (2525ms)
+6008ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (2527ms)
+8873ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Closed]) (2859ms)
+8874ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (2861ms)
+8877ms ║╚Execution stage complete. (8744ms)
+8878ms ╚Event processed successfully (8878ms)
9/18/2019, 12:59:51 AM +748ms
+2ms ╔Received event [Front Bay 3].contact = open with a delay of 120ms
+132ms ║RunTime Analysis CS > 35ms > PS > 44ms > PE > 52ms > CE
+134ms ║Runtime (39888 bytes) successfully initialized in 44ms (v0.3.10e.20190628) (131ms)
+135ms ║╔Execution stage started
+185ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+188ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+190ms ║║Comparison (enum) open is (string) closed = false (2ms)
+193ms ║║Cancelling condition #2’s schedules…
+194ms ║║Condition #2 evaluated false (54ms)
+195ms ║║Cancelling condition #1’s schedules…
+195ms ║║Condition group #1 evaluated false (state changed) (56ms)
+198ms ║║Cancelling statement #3’s schedules…
+3370ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (3162ms)
+3371ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (3164ms)
+6179ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (2803ms)
+6180ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (2804ms)
+8845ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (2658ms)
+8846ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (2660ms)
+8848ms ║╚Execution stage complete. (8713ms)
+8849ms ╚Event processed successfully (8849ms)
9/18/2019, 12:04:25 AM +646ms
+2ms ╔Received event [Rear Bay 5].contact = closed with a delay of 128ms
+128ms ║RunTime Analysis CS > 30ms > PS > 45ms > PE > 52ms > CE
+130ms ║Runtime (39889 bytes) successfully initialized in 45ms (v0.3.10e.20190628) (127ms)
+132ms ║╔Execution stage started
+185ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+187ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+190ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+192ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+194ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+196ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+198ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+200ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+202ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+204ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+207ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+210ms ║║Condition #2 evaluated true (73ms)
+211ms ║║Condition group #1 evaluated true (state did not change) (74ms)
+213ms ║║Cancelling statement #5’s schedules…
+1518ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Closed]) (1295ms)
+1519ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (1297ms)
+2012ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Closed]) (487ms)
+2013ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (489ms)
+2437ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Closed]) (418ms)
+2438ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (420ms)
+2440ms ║╚Execution stage complete. (2309ms)
+2441ms ╚Event processed successfully (2441ms)
9/18/2019, 12:03:25 AM +605ms
+1ms ╔Received event [My home].time/recovery = 1568779405601 with a delay of 4ms
+483ms ║RunTime Analysis CS > 207ms > PS > 214ms > PE > 61ms > CE
+485ms ║Runtime (39900 bytes) successfully initialized in 214ms (v0.3.10e.20190628) (483ms)
+486ms ║╔Execution stage started
+487ms ║╚Execution stage complete. (1ms)
+488ms ╚Event processed successfully (488ms)
9/17/2019, 11:53:48 PM +13ms
+0ms ╔Received event [My home].time/recovery = 1568778828010 with a delay of 3ms
+110ms ║RunTime Analysis CS > 21ms > PS > 39ms > PE > 50ms > CE
+113ms ║Runtime (39897 bytes) successfully initialized in 39ms (v0.3.10e.20190628) (111ms)
+113ms ║╔Execution stage started
+114ms ║╚Execution stage complete. (1ms)
+115ms ╚Event processed successfully (115ms)
9/17/2019, 11:52:58 PM +104ms
+7ms ╔Received event [My home].time/recovery = 1568778778096 with a delay of 7ms
+377ms ║RunTime Analysis CS > 93ms > PS > 174ms > PE > 111ms > CE
+380ms ║Runtime (39900 bytes) successfully initialized in 174ms (v0.3.10e.20190628) (365ms)
+381ms ║╔Execution stage started
+389ms ║╚Execution stage complete. (8ms)
+412ms ╚Event processed successfully (412ms)
9/17/2019, 11:06:21 PM +368ms
+1ms ╔Received event [Front Bay 3].contact = closed with a delay of 135ms
+117ms ║RunTime Analysis CS > 24ms > PS > 43ms > PE > 51ms > CE
+120ms ║Runtime (39893 bytes) successfully initialized in 43ms (v0.3.10e.20190628) (117ms)
+120ms ║╔Execution stage started
+383ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+385ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+387ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+389ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+391ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+393ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+395ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+397ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+399ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+401ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+403ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+406ms ║║Cancelling condition #2’s schedules…
+407ms ║║Condition #2 evaluated true (283ms)
+408ms ║║Cancelling condition #1’s schedules…
+409ms ║║Condition group #1 evaluated true (state changed) (285ms)
+411ms ║║Cancelling statement #5’s schedules…
+7198ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Closed]) (6778ms)
+7199ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (6780ms)
+10115ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Closed]) (2910ms)
+10116ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (2912ms)
+12750ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Closed]) (2628ms)
+12751ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (2630ms)
+12754ms ║╚Execution stage complete. (12633ms)
+12755ms ╚Event processed successfully (12754ms)
9/17/2019, 11:06:21 PM +145ms
+0ms ╔Received event [My home].time/recovery = 1568775981145 with a delay of 0ms
+116ms ║RunTime Analysis CS > 25ms > PS > 39ms > PE > 51ms > CE
+118ms ║Runtime (39900 bytes) successfully initialized in 39ms (v0.3.10e.20190628) (117ms)
+119ms ║╔Execution stage started
+120ms ║╚Execution stage complete. (1ms)
+121ms ╚Event processed successfully (121ms)
9/17/2019, 10:34:19 PM +161ms
+1ms ╔Received event [My home].time/recovery = 1568774059157 with a delay of 4ms
+130ms ║RunTime Analysis CS > 25ms > PS > 41ms > PE > 63ms > CE
+132ms ║Runtime (39900 bytes) successfully initialized in 41ms (v0.3.10e.20190628) (131ms)
+133ms ║╔Execution stage started
+134ms ║╚Execution stage complete. (1ms)
+135ms ╚Event processed successfully (135ms)
9/17/2019, 10:33:52 PM +586ms
+2ms ╔Received event [Front Bay 1].contact = open with a delay of 144ms
+9144ms ║RunTime Analysis CS > 25ms > PS > 9066ms > PE > 53ms > CE
+9145ms ║Piston waited at a semaphore for 9017ms
+9148ms ║Runtime (39963 bytes) successfully initialized in 9066ms (v0.3.10e.20190628) (9145ms)
+9149ms ║╔Execution stage started
+9198ms ║║Comparison (enum) open is (string) closed = false (1ms)
+9201ms ║║Condition #2 evaluated false (48ms)
+9202ms ║║Condition group #1 evaluated false (state did not change) (49ms)
+9204ms ║║Cancelling statement #3’s schedules…
+10195ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (982ms)
+10196ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (984ms)
+10571ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (367ms)
+10572ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (369ms)
+11078ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (498ms)
+11079ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (500ms)
+11081ms ║╚Execution stage complete. (1932ms)
+11082ms ╚Event processed successfully (11082ms)
9/17/2019, 10:32:56 PM +615ms
+0ms ╔Received event [My home].time/recovery = 1568773976615 with a delay of 0ms
+132ms ║RunTime Analysis CS > 24ms > PS > 50ms > PE > 58ms > CE
+134ms ║Runtime (39898 bytes) successfully initialized in 50ms (v0.3.10e.20190628) (133ms)
+135ms ║╔Execution stage started
+136ms ║╚Execution stage complete. (1ms)
+137ms ╚Event processed successfully (137ms)
9/17/2019, 9:18:55 PM +85ms
+0ms ╔Received event [My home].time/recovery = 1568769535081 with a delay of 4ms
+110ms ║RunTime Analysis CS > 19ms > PS > 40ms > PE > 51ms > CE
+113ms ║Runtime (39898 bytes) successfully initialized in 40ms (v0.3.10e.20190628) (111ms)
+114ms ║╔Execution stage started
+114ms ║╚Execution stage complete. (1ms)
+115ms ╚Event processed successfully (115ms)
9/17/2019, 8:50:55 PM +90ms
+1ms ╔Received event [My home].time/recovery = 1568767855086 with a delay of 4ms
+133ms ║RunTime Analysis CS > 26ms > PS > 50ms > PE > 56ms > CE
+135ms ║Runtime (39898 bytes) successfully initialized in 50ms (v0.3.10e.20190628) (133ms)
+136ms ║╔Execution stage started
+137ms ║╚Execution stage complete. (1ms)
+138ms ╚Event processed successfully (138ms)
9/17/2019, 8:48:34 PM +207ms
+0ms ╔Received event [My home].time/recovery = 1568767714202 with a delay of 5ms
+124ms ║RunTime Analysis CS > 22ms > PS > 45ms > PE > 56ms > CE
+126ms ║Runtime (39898 bytes) successfully initialized in 45ms (v0.3.10e.20190628) (125ms)
+127ms ║╔Execution stage started
+128ms ║╚Execution stage complete. (1ms)
+129ms ╚Event processed successfully (129ms)
9/17/2019, 8:48:15 PM +626ms
+1ms ╔Received event [Rear Bay 6].contact = closed with a delay of 139ms
+3875ms ║RunTime Analysis CS > 23ms > PS > 3801ms > PE > 51ms > CE
+3876ms ║Piston waited at a semaphore for 3756ms
+3878ms ║Runtime (39958 bytes) successfully initialized in 3801ms (v0.3.10e.20190628) (3876ms)
+3879ms ║╔Execution stage started
+3946ms ║║Comparison (enum) open is (string) closed = false (1ms)
+3949ms ║║Condition #2 evaluated false (66ms)
+3950ms ║║Condition group #1 evaluated false (state did not change) (68ms)
+3952ms ║║Cancelling statement #3’s schedules…
+5186ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (1225ms)
+5187ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (1227ms)
+5577ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (383ms)
+5578ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (385ms)
+5962ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (378ms)
+5963ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (380ms)
+5965ms ║╚Execution stage complete. (2087ms)
+5966ms ╚Event processed successfully (5967ms)
9/17/2019, 8:45:18 PM +218ms
+0ms ╔Received event [My home].time/recovery = 1568767518213 with a delay of 4ms
+103ms ║RunTime Analysis CS > 23ms > PS > 33ms > PE > 48ms > CE
+106ms ║Runtime (39892 bytes) successfully initialized in 33ms (v0.3.10e.20190628) (104ms)
+107ms ║╔Execution stage started
+108ms ║╚Execution stage complete. (1ms)
+109ms ╚Event processed successfully (108ms)
9/17/2019, 8:44:38 PM +578ms
+2ms ╔Received event [Rear Bay 6].contact = open with a delay of 130ms
+120ms ║RunTime Analysis CS > 23ms > PS > 44ms > PE > 53ms > CE
+122ms ║Runtime (39884 bytes) successfully initialized in 44ms (v0.3.10e.20190628) (120ms)
+123ms ║╔Execution stage started
+176ms ║║Comparison (enum) open is (string) closed = false (1ms)
+179ms ║║Condition #2 evaluated false (52ms)
+180ms ║║Condition group #1 evaluated false (state did not change) (53ms)
+182ms ║║Cancelling statement #3’s schedules…
+3357ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (3167ms)
+3358ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (3168ms)
+3874ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (510ms)
+3875ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (512ms)
+4387ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (505ms)
+4388ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (507ms)
+4390ms ║╚Execution stage complete. (4267ms)
+4391ms ╚Event processed successfully (4391ms)
9/17/2019, 8:44:37 PM +180ms
+1ms ╔Received event [My home].time/recovery = 1568767477176 with a delay of 4ms
+335ms ║RunTime Analysis CS > 225ms > PS > 46ms > PE > 64ms > CE
+338ms ║Runtime (39895 bytes) successfully initialized in 46ms (v0.3.10e.20190628) (336ms)
+339ms ║╔Execution stage started
+340ms ║╚Execution stage complete. (1ms)
+341ms ╚Event processed successfully (340ms)
9/17/2019, 8:44:20 PM +760ms
+2ms ╔Received event [Front Bay 4].contact = open with a delay of 128ms
+2492ms ║RunTime Analysis CS > 24ms > PS > 2410ms > PE > 58ms > CE
+2493ms ║Piston waited at a semaphore for 2342ms
+2496ms ║Runtime (39963 bytes) successfully initialized in 2410ms (v0.3.10e.20190628) (2492ms)
+2496ms ║╔Execution stage started
+2550ms ║║Comparison (enum) open is (string) closed = false (1ms)
+2553ms ║║Condition #2 evaluated false (53ms)
+2554ms ║║Condition group #1 evaluated false (state did not change) (54ms)
+2556ms ║║Cancelling statement #3’s schedules…
+3834ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (1269ms)
+3835ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (1271ms)
+4462ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (621ms)
+4463ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (623ms)
+4972ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (503ms)
+4973ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (505ms)
+4975ms ║╚Execution stage complete. (2479ms)
+4976ms ╚Event processed successfully (4976ms)
9/17/2019, 8:40:32 PM +292ms
+2ms ╔Received event [Rear Bay 5].contact = open with a delay of 137ms
+137ms ║RunTime Analysis CS > 43ms > PS > 42ms > PE > 51ms > CE
+139ms ║Runtime (39890 bytes) successfully initialized in 42ms (v0.3.10e.20190628) (137ms)
+140ms ║╔Execution stage started
+191ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+193ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+195ms ║║Comparison (enum) open is (string) closed = false (1ms)
+198ms ║║Condition #2 evaluated false (54ms)
+199ms ║║Condition group #1 evaluated false (state did not change) (55ms)
+201ms ║║Cancelling statement #3’s schedules…
+3237ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (3028ms)
+3238ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (3030ms)
+3629ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (385ms)
+3630ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (387ms)
+3987ms ║║Executed physical command [EcobeeTherm: West Garage].setThermostatProgram([Doors Open]) (351ms)
+3988ms ║║Executed [EcobeeTherm: West Garage].setThermostatProgram (353ms)
+3990ms ║╚Execution stage complete. (3850ms)
+3991ms ╚Event processed successfully (3991ms)
9/17/2019, 8:25:41 PM +154ms
+1ms ╔Received event [My home].time/recovery = 1568766341153 with a delay of 1ms
+142ms ║RunTime Analysis CS > 24ms > PS > 60ms > PE > 57ms > CE
+144ms ║Runtime (39900 bytes) successfully initialized in 60ms (v0.3.10e.20190628) (143ms)
+145ms ║╔Execution stage started
+146ms ║╚Execution stage complete. (1ms)
+147ms ╚Event processed successfully (147ms)
9/17/2019, 6:58:40 PM +247ms
+0ms ╔Received event [My home].time/recovery = 1568761120243 with a delay of 3ms
+140ms ║RunTime Analysis CS > 30ms > PS > 57ms > PE > 53ms > CE
+142ms ║Runtime (39900 bytes) successfully initialized in 57ms (v0.3.10e.20190628) (141ms)
+143ms ║╔Execution stage started
+144ms ║╚Execution stage complete. (1ms)
+145ms ╚Event processed successfully (145ms)
9/17/2019, 6:53:49 PM +704ms
+1ms ╔Received event [Front Bay 3].contact = closed with a delay of 110ms
+113ms ║RunTime Analysis CS > 21ms > PS > 40ms > PE > 52ms > CE
+116ms ║Runtime (39891 bytes) successfully initialized in 40ms (v0.3.10e.20190628) (113ms)
+117ms ║╔Execution stage started
+166ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+168ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+170ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+172ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+174ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+177ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+179ms ║║Comparison (enum) open is (string) closed = false (1ms)
+182ms ║║Condition #2 evaluated false (61ms)
+183ms ║║Condition group #1 evaluated false (state did not change) (62ms)
+185ms ║║Cancelling statement #3’s schedules…
+1117ms ║║Executed physical command [EcobeeTherm: East Garage].setThermostatProgram([Doors Open]) (924ms)
+1118ms ║║Executed [EcobeeTherm: East Garage].setThermostatProgram (926ms)
+1608ms ║║Executed physical command [EcobeeTherm: South garage].setThermostatProgram([Doors Open]) (483ms)
+1609ms ║║Executed [EcobeeTherm: South garage].setThermostatProgram (485ms)

Eric182 · 2019-09-18 16:04:48 UTC

There are numerous threads recently about recent st sluggishness.

Pistons that have been working fine have been failing for many users within the last six days.

tange1 · 2019-09-18 18:52:44 UTC

According to the ST page isn’t the issue resolved?

tange1 · 2019-09-19 21:30:27 UTC

I’d appreciate if anyone else can help me out on this - i’m still seeing inconsistent behavior. I’ve noticed that if I re-save the piston and it resubscribes to all events it seems to run smooth, for awhile. I can’t find the triggering issue - i’m not sure if its in my logic, in ST or in ecobee?

WCmore · 2019-09-20 03:29:46 UTC

Your giant log looks like everything processed correctly.

7:15:41 AM =        closed = false
.setThermostatProgram([Doors Open])
-------------------------------------
6:00:28 AM =        closed = true 
.setThermostatProgram([Doors Closed])
-------------------------------------
6:00:09 AM =        closed = false
.setThermostatProgram([Doors Open])
-------------------------------------
5:28:18 AM =        closed = true 
.setThermostatProgram([Doors Closed]) 
-------------------------------------
1:00:42 AM =        closed = true
.setThermostatProgram([Doors Closed]) 
-------------------------------------
12:04:25 AM =       closed = true 
.setThermostatProgram([Doors Closed]) 
-------------------------------------
11:06:21 PM =       closed = true 
.setThermostatProgram([Doors Closed])
-------------------------------------
6:53:49 PM =        closed = false
.setThermostatProgram([Doors Open])

For future reference, I would:

Clear the logs
Run a test
Post the log showing the error.

Nobody wants to dig thru sixteen pages of logs!!!

At a quick skim, the only issue I see with your log is the 25 occurrences of “recovery”.
(during 15 hours!?!)

The most common reasons for this is either:

Too many triggers in this piston (you have a whopping 22!)
and/or
Too many triggers in other pistons going off within a short time
and/or
Too much SmartHome logic processing at the time (loops / while etc)
and/or
Too much chatter on your home network at that time (gaming, heavy downloading / streaming etc)

tange1 · 2019-09-20 19:29:13 UTC

Thanks for the feedback. I can share a few thoughts. Yes, I have quite a few triggers. I would have guessed 11 based on the 11 sensors? Maybe that number is doubled based on open and closed states (2 per?). I need to trigger based on 11 garage doors. If the issue is with the number of triggers, is there different logic i could use such that any open door turns the 3 thermostats to doors open?

I dont understand what a recovery is. I’ve used pistions before but this is the first i’ve seen recovery in the logs.

I have no other pistions, no other smart home logics built anywhere else in this whole solution.

The ST hub is on a small business network, but i did put it on our guest network which is probably pretty busy. I could have it moved to a less busy network leg if that would help?

I will re-test in a much smaller window of time.

thanks in advance.

WCmore · 2019-09-21 03:03:26 UTC

Yes. The piston runs thru the code top to bottom when any of the 11 devices OPENS or CLOSES.

Well, normally I would say, “You likely have pistons already monitoring those contact sensors… Why not just add a single line to THOSE pistons to change the thermostat to Door Open. This way, only one piston tries to execute at each contact change.”

But you said you have no other pistons…

and you also said you’ve used pistons before…

So I don’t know what to tell you, LOL

Recovery runs (or tries to run) shortly after an event did not process in a timely manner.

This is always preferred, whenever there is an option.

Another advanced strategy I use, is to change the settings on the router, to prioritize the ST hub as the highest priority. Some routers call this QoS or Quality of Service. This works well if you assign your hub a static IP, or prioritize based on MAC address.

This last tip will not resolve too much chatter in the ST network, but it does help keep the hub at the front of the line when compared to other devices.

tange1 · 2019-09-23 22:30:05 UTC

I’m assuming the majority of my problems are that doors are constantly changing state, sometimes quickly and the system isn’t keeping up. In an attempt to alleviate all the calls I made a few adjustments, delaying changing the thermostat till the doors have been open awhile and not sending door closed messages more than i have to.

This is having an unintended issue: when a door opens, the 10 minute timer seems to run. I think the problem is if i close all doors, i still see the 10 minute count down. Seems like the countdown ends, the state changes and it switches to doors open thermostat program despire the doors being closed. Does Webcore re-evaluate at the end of the 10 minutes to see if the doors are still open?

WCmore · 2019-09-24 03:12:02 UTC

I think you will have issues placing an IF trigger inside an IF trigger. The second IF (line 31) may not ever fire correctly.

If it was in it’s own block (outside of other IFs), you’d likely get better results.