1) Give a description of the problem
Variables in Never Cancel switch block aren’t updated, possibly cancelled.
2) What is the expected behavior?
90+ % of the time the variables are updated as expected but sometimes they aren’t updated at all.
3) What is happening/not happening?
This piston generates tiles and fuel streams for home energy monitoring (HEM) devices. The tiles are updated on each event but fuel streams are designed to ignore variations below a set threshold or otherwise are permitted to write a keep alive point every 1-2 hours depending on the total number of devices monitored. WARNING! This piston handles a large number of events! So many that it is strongly recommended not to use this piston with more than 8 devices without adjusting the reporting rate of said devices to reduce the event load. You can possibly overload your system! Each device is generating on the order of 132+ events per hour with the typical default settings. My three devices generate around 400 events/hour.
Normally I get nice fuel streams like this:
but every once in a while i see this:
The interesting thing about the spiky glitches is they point to a very specific problem. First, let me point out some specifics. The spacing between the spiky points is 5 minutes, the natural reporting frequency for this value for this device. The device should be inhibited from writing data points for an hour if the timeDelayEnergy[] variable is updated properly and there are no out of range values (there aren’t). Second both in the chart and the log the next variable, lastVolts[], is also not updated. I was able to capture data for one instance as seen in the image above between 8:32:50 and 8:37:50. The debug log captured for just 7.5 minutes around these events is around 90000 characters (almost two full posts with the 50000 character limit here). In the interest of not scaring everyone away with those massive logs, I’m only posting the greatest hits version with the understanding that the massive logs are available if requested.
**4) Post a Green Snapshot of the piston
5) Attach any logs (From ST IDE and by turning logging level to Full)
8:32:50 event log:
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: info ║ Setting up scheduled job for Tue, Dec 11 2018 @ 8:41:52 PM EST (in 539.937s)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: trace ║║ Executed virtual command setVariable (4ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (enum) on == (enum) on >> (boolean) true
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke | 1.8 kwh] | $ + (string) 0.38 >> (string) [whitesmoke | 1.8 kwh] | $0.38
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke | + (string) 1.8 >> (string) [whitesmoke | 1.8
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (decimal) 1.8 * (decimal) 0.21 >> (decimal) 0.378
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke b | 14.4 W[fa-layers | [color-darkgreen | :fas fa-bolt data-fa-transform="shrink-7 down-3.5 right-3.5":] [color-greenyellow | :fas fa-bolt data-fa-transform="shrink-7 down-4 right-4":] [fa-layers-counter fa-1x | 121.5 V + (string) ] ] >> (string) [whitesmoke b | 14.4 W[fa-layers | [color-darkgreen | :fas fa-bolt data-fa-transform="shrink-7 down-3.5 right-3.5":] [color-greenyellow | :fas fa-bolt data-fa-transform="shrink-7 down-4 right-4":] [fa-layers-counter fa-1x | 121.5 V ] ]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke b | + (string) 14.4 >> (string) [whitesmoke b | 14.4
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (decimal) 121.5 == (decimal) 0.0 >> (boolean) false
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 120 + (string) V >> (string) 120 V
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: trace ║║ Executed virtual command setVariable (4ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: trace ║║ Executed virtual command setVariable (5ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: error ║║ 3-Xmas Tree 120.5V/121.5V
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 3-Xmas Tree + (string) >> (string) 3-Xmas Tree
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 3 + (string) - >> (string) 3-
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) Electrical \ Xmas Tree + (string) >> (string) Electrical \ Xmas Tree
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: info ╔ Event processed successfully (2890ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: trace ║╔ Execution stage complete. (2624ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: trace ║║ Executed virtual command setTile (1ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke | 1.8 kwh] | $0.38 + (string) ] >> (string) [whitesmoke | 1.8 kwh] | $0.38]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke | 1.8 + (string) kwh] | $ >> (string) [whitesmoke | 1.8 kwh] | $
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Cancelling statement #300's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (enum) on == (enum) on >> (boolean) true
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) [whitesmoke b | 14.4 + (string) W[fa-layers | [color-darkgreen | :fas fa-bolt data-fa-transform="shrink-7 down-3.5 right-3.5":] [color-greenyellow | :fas fa-bolt data-fa-transform="shrink-7 down-4 right-4":] [fa-layers-counter fa-1x | >> (string) [whitesmoke b | 14.4 W[fa-layers | [color-darkgreen | :fas fa-bolt data-fa-transform="shrink-7 down-3.5 right-3.5":] [color-greenyellow | :fas fa-bolt data-fa-transform="shrink-7 down-4 right-4":] [fa-layers-counter fa-1x |
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 121.5 + (string) V >> (string) 121.5 V
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) Xmas Tree is [greenyellow | On] + (string) >> (string) Xmas Tree is [greenyellow | On]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) Xmas Tree is + (string) [greenyellow | On] >> (string) Xmas Tree is [greenyellow | On]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) Xmas Tree + (string) is >> (string) Xmas Tree is
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (enum) on == (enum) on >> (boolean) true
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Cancelling statement #357's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: trace ║║ Executed virtual command log (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Evaluating switch with values [[i:10:null:0, v:[t:string, v:voltage, vt:string]]]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 3-Xmas Tree 120.5V/ + (string) 121.5 >> (string) 3-Xmas Tree 120.5V/121.5
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 3-Xmas Tree + (string) 120.5 >> (string) 3-Xmas Tree 120.5
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (integer) 3 + (integer) 1 >> (integer) 4
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Fast executing schedules, waiting for 1979ms to sync up
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Calculating (string) 3- + (string) Xmas Tree >> (string) 3-Xmas Tree
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Calculating (string) Electrical \ + (string) Xmas Tree >> (string) Electrical \ Xmas Tree
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:52 PM: debug ║║ Comparison (string) voltage is (string) power = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: info smartapp_pause called by smartAppName=webCoRE Piston, value=1979, smartAppVersionId=2d25d312-4e22-4153-89bb-9f21e5f58c82
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition group #369 evaluated false (state did not change) (8ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition #370 evaluated false (6ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition #364 evaluated true (9ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: trace ║║ Executed virtual command wait (1ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Cancelling condition #298's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Cancelling condition #299's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Cancelling statement #365's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (datetime) 1544578083573 is_less_than (datetime) 1544578370409 = true (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (string) voltage is (string) energy = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition group #363 evaluated true (state did not change) (11ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (decimal) 121.5 is_different_than (decimal) 120.5 = true (3ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Evaluating switch with values [[i:10:null:0, v:[t:string, v:voltage, vt:string]]]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition group #298 evaluated true (state changed) (12ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition #299 evaluated true (9ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: trace ║║ Executed virtual command setVariable (4ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Cancelling statement #16's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition #274 evaluated false (7ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (string) voltage is (string) voltage = true (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition group #333 evaluated false (state did not change) (17ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (string) voltage is (string) power = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (integer) 3 is_different_than (integer) 3 = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: trace ║╚ Execution stage started
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: trace ║║ Executed virtual command setVariable (4ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║ RunTime Analysis CS > 30ms > PS > 128ms > PE > 88ms > CE
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Calculating (integer) 2 + (integer) 1 >> (integer) 3
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition group #273 evaluated false (state did not change) (9ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Comparison (boolean) true is (boolean) false = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: debug ║║ Condition #334 evaluated false (14ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: trace ║ Runtime (84937 bytes) successfully initialized in 128ms (v0.3.109.20181207) (248ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:32:50 PM: info ╚ Received event [Xmas Tree].voltage = 121.5 with a delay of 148ms
8:37:50 event log:
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) 121.8 + (string) V >> (string) 121.8 V
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Cancelling condition #299's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Comparison (string) voltage is (string) energy = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Comparison (string) voltage is (string) power = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Cancelling statement #16's schedules...
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (enum) on == (enum) on >> (boolean) true
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) [whitesmoke b | 14.4 W[fa-layers | [color-darkgreen | :fas fa-bolt data-fa-transform="shrink-7 down-3.5 right-3.5":] [color-greenyellow | :fas fa-bolt data-fa-transform="shrink-7 down-4 right-4":] [fa-layers-counter fa-1x | + (string) 121.8 V >> (string) [whitesmoke b | 14.4 W[fa-layers | [color-darkgreen | :fas fa-bolt data-fa-transform="shrink-7 down-3.5 right-3.5":] [color-greenyellow | :fas fa-bolt data-fa-transform="shrink-7 down-4 right-4":] [fa-layers-counter fa-1x | 121.8 V
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) [whitesmoke b | + (string) 14.4 >> (string) [whitesmoke b | 14.4
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) Xmas Tree is + (string) [greenyellow | On] >> (string) Xmas Tree is [greenyellow | On]
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: trace ║║ Executed virtual command log (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: error ║║ 3-Xmas Tree 120.5V/121.8V
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) 3-Xmas Tree 120.5V/ + (string) 121.8 >> (string) 3-Xmas Tree 120.5V/121.8
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) 3-Xmas Tree + (string) 120.5 >> (string) 3-Xmas Tree 120.5
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) 3-Xmas Tree + (string) >> (string) 3-Xmas Tree
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) 3 + (string) - >> (string) 3-
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (string) Electrical \ + (string) Xmas Tree >> (string) Electrical \ Xmas Tree
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Comparison (string) voltage is (string) voltage = true (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Comparison (string) voltage is (string) power = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:52 PM: debug ║║ Calculating (integer) 3 + (integer) 1 >> (integer) 4
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: info smartapp_pause called by smartAppName=webCoRE Piston, value=1977, smartAppVersionId=2d25d312-4e22-4153-89bb-9f21e5f58c82
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Condition group #369 evaluated false (state did not change) (9ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Comparison (string) voltage is (string) tile = false (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: trace ║║ Executed virtual command wait (1ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Condition #364 evaluated true (10ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Comparison (decimal) 121.8 is_different_than (decimal) 120.5 = true (3ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Condition #299 evaluated true (10ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Comparison (datetime) 1544578083573 is_less_than (datetime) 1544578670378 = true (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Comparison (string) voltage is (string) voltage = true (2ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Calculating (integer) 2 + (integer) 1 >> (integer) 3
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Condition group #273 evaluated false (state did not change) (9ms)
8854c8ff-3fd4-401f-b001-a3002bb68336 8:37:50 PM: debug ║║ Condition group #333 evaluated false (state did not change) (17ms)
RE: @WCmore, @ipaterson, @Robin