genielabs / HomeGenie

HomeGenie, the programmable automation intelligence
https://homegenie.it
GNU General Public License v3.0
387 stars 154 forks source link

Log Entry Duplication [BUG] #454

Closed EnGamma closed 9 months ago

EnGamma commented 1 year ago

Version Which HomeGenie version/OS/.NET framework version are you using. (REQUIRED) linux-arm 1.4.0-beta.13

Describe the bug Duplication (at least) of log entries causing log file size to increase at >= twice normal rate.

Code to Reproduce Write a small snippet to isolate your bug and could be possible to our team test. (REQUIRED) N/A

Expected behavior Single entries for each logged event.

Screenshots/Stacktrace Sample excerpt: .... 2023-01-12 07:29:16.1253 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0) 2023-01-12 07:29:16.1253 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:16.1253 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0 2023-01-12 07:29:16.2299 Debug ZWaveMessage (RawData=01-09-00-04-00-03-03-80-03-00-71) 2023-01-12 07:29:16.2299 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=Battery) 2023-01-12 07:29:16.2299 Debug 01-09-00-04-00-03-03-80-03-00-71 2023-01-12 07:29:16.2299 Debug 06 2023-01-12 07:29:16.2299 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0) 2023-01-12 07:29:16.2299 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:16.2484 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0 2023-01-12 07:29:16.3503 Debug 01-0E-00-04-08-03-08-31-05-04-64-00-03-95-7B-4F 2023-01-12 07:29:16.3503 Debug ZWaveMessage (RawData=01-0E-00-04-08-03-08-31-05-04-64-00-03-95-7B-4F) 2023-01-12 07:29:16.3503 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=SensorMultilevel) 2023-01-12 07:29:16.3569 Debug 06 2023-01-12 07:29:16.3569 Debug NodeUpdated (NodeId=3, Parameter=MeterPower, Value=234.875) 2023-01-12 07:29:16.3569 Info HomeAutomation.ZWave 3 ZWave Node Sensor.Power 234.875 2023-01-12 07:29:16.3569 Debug 01-0E-00-04-00-03-08-31-05-04-64-00-03-95-7B-47 2023-01-12 07:29:16.3569 Debug ZWaveMessage (RawData=01-0E-00-04-00-03-08-31-05-04-64-00-03-95-7B-47) 2023-01-12 07:29:16.3569 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=SensorMultilevel) 2023-01-12 07:29:16.3569 Debug 06 2023-01-12 07:29:16.3569 Debug NodeUpdated (NodeId=3, Parameter=MeterPower, Value=234.875) 2023-01-12 07:29:16.3827 Info HomeAutomation.ZWave 3 ZWave Node Sensor.Power 234.875 2023-01-12 07:29:16.5845 Debug 01-14-00-04-08-03-0E-32-02-21-64-00-55-FE-1D-00-0A-00-55-FE-1D-95 2023-01-12 07:29:16.5845 Debug ZWaveMessage (RawData=01-14-00-04-08-03-0E-32-02-21-64-00-55-FE-1D-00-0A-00-55-FE-1D-95) 2023-01-12 07:29:16.5845 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=Meter) 2023-01-12 07:29:16.5856 Debug 06 2023-01-12 07:29:16.5856 Debug NodeUpdated (NodeId=3, Parameter=MeterKwHour, Value=5635.613) 2023-01-12 07:29:16.5856 Info HomeAutomation.ZWave 3 ZWave Node Meter.KilowattHour 5635.613 2023-01-12 07:29:16.6875 Debug 01-14-00-04-00-03-0E-32-02-21-64-00-55-FE-1D-00-0A-00-55-FE-1D-9D 2023-01-12 07:29:16.6875 Debug ZWaveMessage (RawData=01-14-00-04-00-03-0E-32-02-21-64-00-55-FE-1D-00-0A-00-55-FE-1D-9D) 2023-01-12 07:29:16.6875 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=Meter) 2023-01-12 07:29:16.6875 Debug 06 2023-01-12 07:29:16.6875 Debug NodeUpdated (NodeId=3, Parameter=MeterKwHour, Value=5635.613) 2023-01-12 07:29:16.6875 Info HomeAutomation.ZWave 3 ZWave Node Meter.KilowattHour 5635.613 2023-01-12 07:29:16.8793 Info HomeAutomation.EnergyMonitor 1 - EnergyMonitor.WattCounter 10316.925003577036 2023-01-12 07:29:16.8968 Info HomeAutomation.EnergyMonitor 1 - EnergyMonitor.KwCounter 10.316925003577037 2023-01-12 07:29:16.9416 Info HomeAutomation.EnergyMonitor 1 - EnergyMonitor.WattCounter.Today 4888.515632910975 2023-01-12 07:29:16.9902 Info HomeAutomation.EnergyMonitor 1 - EnergyMonitor.KwCounter.Today 4.888515632910975 2023-01-12 07:29:17.4265 Error System.Exception: X10 CM15Pro device not connected. 2023-01-12 07:29:21.4636 Error System.Exception: X10 CM15Pro device not connected. 2023-01-12 07:29:25.5201 Error System.Exception: X10 CM15Pro device not connected. 2023-01-12 07:29:26.1999 Debug 01-09-00-04-08-03-03-80-03-00-79 2023-01-12 07:29:26.1999 Debug ZWaveMessage (RawData=01-09-00-04-08-03-03-80-03-00-79) 2023-01-12 07:29:26.1999 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=Battery) 2023-01-12 07:29:26.1999 Debug 06 2023-01-12 07:29:26.1999 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0) 2023-01-12 07:29:26.2054 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:26.2249 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0 2023-01-12 07:29:26.2269 Debug 01-09-00-04-00-03-03-80-03-00-71 2023-01-12 07:29:26.2269 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=Battery) 2023-01-12 07:29:26.2269 Debug ZWaveMessage (RawData=01-09-00-04-00-03-03-80-03-00-71) 2023-01-12 07:29:26.2269 Debug 06 2023-01-12 07:29:26.2269 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0) 2023-01-12 07:29:26.2807 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:26.3432 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0 2023-01-12 07:29:26.3432 Debug 01-0E-00-04-08-03-08-31-05-04-64-00-03-69-0C-C4 2023-01-12 07:29:26.3432 Debug ZWaveMessage (RawData=01-0E-00-04-08-03-08-31-05-04-64-00-03-69-0C-C4) 2023-01-12 07:29q:26.3432 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=SensorMultilevel) 2023-01-12 07:29:26.3477 Debug 06 2023-01-12 07:29:26.3477 Debug NodeUpdated (NodeId=3, Parameter=MeterPower, Value=223.5) 2023-01-12 07:29:26.3637 Info HomeAutomation.ZWave 3 ZWave Node Sensor.Power 223.5 2023-01-12 07:29:26.4657 Debug 01-0E-00-04-00-03-08-31-05-04-64-00-03-69-0C-CC 2023-01-12 07:29:26.4657 Debug ZWaveMessage (RawData=01-0E-00-04-00-03-08-31-05-04-64-00-03-69-0C-CC) 2023-01-12 07:29:26.4657 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=3, Type=Request, Function=ApplicationCommandHandler, CommandClass=SensorMultilevel) 2023-01-12 07:29:26.4657 Debug 06 ..

Additional context Most, but not all entries are duplicated

genemars commented 1 year ago

Not considering the X10 CM15Pro device not connected. one, exactly what messages you consider duplicated in the log you posted? They all have different instance and checksum (last byte).

EnGamma commented 1 year ago

The duplication is in z-wave device reports. Here's some mqtt output I just captured:

hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:58.1109282Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:58.1375976Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"304.75","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:58.240482Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"304.75","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:58.3440306Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.702","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:58.4460517Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.702","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:58.5509141Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts","Value":"28.685","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:59.7563797Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts","Value":"28.685","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:59.8622482Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts.4","Value":"7.853","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:21:59.9659935Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts.4","Value":"7.853","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:00.0693418Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:08.1625135Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:08.2640672Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"296.625","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:08.2909875Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"296.625","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:08.3123557Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.702","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:08.5524685Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.702","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:08.5678606Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.1269307Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.1627414Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"304.125","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.3815121Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"304.125","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.4171692Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.702","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.615231Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.702","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.615231Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/10/event {"Name":"Meter.Watts","Value":"1372.5","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:18.944002Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/40/event {"Name":"Meter.Watts","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:21.7665961Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:28.1126707Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:28.1501516Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"307.375","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:28.257368Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"307.375","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:28.3931586Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:28.5304026Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:28.5466264Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:38.0941873Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:38.1085879Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"286.375","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:38.3112235Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"286.375","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:38.4149595Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:38.5629206Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:38.5629206Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:48.1100983Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:48.1376418Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"292.375","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:48.2401656Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"292.375","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:48.3428861Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:48.4478291Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:48.5615152Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/40/event {"Name":"Meter.Watts","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:51.8774858Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/10/event {"Name":"Meter.Watts","Value":"1365.75","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:52.5817928Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/10/event {"Name":"Meter.Watts","Value":"1365.75","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:52.6849083Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/10/event {"Name":"Meter.Watts.1","Value":"1160.625","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:52.793484Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/10/event {"Name":"Meter.Watts.2","Value":"205.125","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:52.932646Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:58.056966Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:58.1706099Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"290.5","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:58.2762728Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"290.5","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:58.381213Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:58.48578Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:58.5882248Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts","Value":"15.835","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:59.795082Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts","Value":"15.835","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:22:59.8470633Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts.2","Value":"2.704","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:00.0542176Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts.2","Value":"2.704","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:00.0720866Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts.4","Value":"10.776","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:00.1857097Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/9/event {"Name":"Meter.Watts.4","Value":"10.776","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:00.2281994Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/10/event {"Name":"Meter.Watts","Value":"1380.875","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:03.7979496Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:08.0838745Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:08.0994935Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"317.75","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:08.3028105Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"317.75","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:08.4055235Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:08.5093977Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:08.6144894Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:18.103623Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:18.2133964Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"305","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:18.3201483Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"305","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:18.5483343Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:18.6570293Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.707","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:18.7173085Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/40/event {"Name":"Meter.Watts","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:21.8192332Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:28.1405732Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Status.Battery","Value":"0","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:28.162205Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"305.125","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:28.2659658Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"305.125","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:28.3824072Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.712","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:28.5029039Z","NeedsUpdate":false} hg-104/HomeAutomation.ZWave/3/event {"Name":"Meter.KilowattHour","Value":"5817.712","Description":"","FieldType":"","UpdateTime":"2023-03-02T18:23:28.5174768Z","NeedsUpdate":false}

I don't think these duplicate reports are being sent by the devices themselves. The devices were never configured for such frequent reports only milliseconds apart and I'm not even sure they are capable of reporting so frequently. Look closely at nodes 3, 9, and 10 power reports, for example. This make me believe that there is something in the code that is duplicating logging/reporting of a single device report.

EnGamma commented 1 year ago

Back to the original log output, here are some excerpts that I think illustrate the same thing:

2023-01-12 07:29:16.1253 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0 2023-01-12 07:29:16.1253 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:16.1253 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0

-------- about 100ms later:

2023-01-12 07:29:16.2299 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0) 2023-01-12 07:29:16.2299 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:16.2484 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0

genemars commented 1 year ago

Back to the original log output, here are some excerpts that I think illustrate the same thing:

2023-01-12 07:29:16.1253 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0 2023-01-12 07:29:16.1253 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:16.1253 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0

-------- about 100ms later:

2023-01-12 07:29:16.2299 Debug NodeUpdated (NodeId=3, Parameter=Battery, Value=0) 2023-01-12 07:29:16.2299 Info HomeAutomation.ZWave 3 ZWave Node ZWaveNode.Battery 0 2023-01-12 07:29:16.2484 Info HomeAutomation.ZWave 3 ZWave Node Status.Battery 0

Yes, but the raw data is different, meaning that is the device that is sending the message twice.

EnGamma commented 1 year ago

This time, I filtered mqtt output to only Node 3 Sensor.Power and I edited out blank JSON fields for simplicity:

hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"213.25","UpdateTime":"2023-03-02T19:10:28.7885432Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"213.25","UpdateTime":"2023-03-02T19:10:28.8915586Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"228.375","UpdateTime":"2023-03-02T19:10:38.6624015Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"228.375","UpdateTime":"2023-03-02T19:10:38.6860084Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"213.375","UpdateTime":"2023-03-02T19:10:48.6393244Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"213.375","UpdateTime":"2023-03-02T19:10:48.7426647Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"209.75","UpdateTime":"2023-03-02T19:10:58.9950359Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"209.75","UpdateTime":"2023-03-02T19:10:59.0003934Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"210.5","UpdateTime":"2023-03-02T19:11:08.6489617Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"210.5","UpdateTime":"2023-03-02T19:11:08.7550209Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"219.5","UpdateTime":"2023-03-02T19:11:18.6675428Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"219.5","UpdateTime":"2023-03-02T19:11:18.6931549Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"208.125","UpdateTime":"2023-03-02T19:11:28.6420904Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"208.125","UpdateTime":"2023-03-02T19:11:28.7683771Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"217.875","UpdateTime":"2023-03-02T19:11:38.6214111Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"217.875","UpdateTime":"2023-03-02T19:11:38.7332348Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"224.5","UpdateTime":"2023-03-02T19:11:48.6391584Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"224.5","UpdateTime":"2023-03-02T19:11:48.7444766Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"221.375","UpdateTime":"2023-03-02T19:11:58.6245848Z"} hg-104/HomeAutomation.ZWave/3/event {"Name":"Sensor.Power","Value":"221.375","UpdateTime":"2023-03-02T19:11:58.7277817Z"

Note the longer gap between the double reports, which seems like a more reasonable report interval. What is setting the reporting interval? Are the devices being polled by HG1.4? This is very different behavior from what I saw with HG1.3 and I have done nothing to change the zwave devices internal settings for report intervals.

EnGamma commented 1 year ago

I use both the log output to generate my own custom mqtt messages and I've been looking at the built-in HG mqtt output for possible use. But for each of these I'm getting twice the necessary communication traffic.

EnGamma commented 1 year ago

Yes, but the raw data is different, meaning that is the device that is sending the message twice.

Is HG somehow requesting a second report, each time the device reports?

genemars commented 1 year ago

Do you see any automation program under the Z-Wave group? If so, disable all of them and see what happen.

By the way I have a similar issue with my Z-Wave meter, but it has always been like this also with HG 1.3, so not sure if it's the same thing. Other Z-Wave devices that I also set to report basic and meter changes do not have this duplicated report issue.

EnGamma commented 1 year ago

Do you see any automation program under the Z-Wave group? If so, disable all of them and see what happen.

By the way I have a similar issue with my Z-Wave meter, but it has always been like this also with HG 1.3, so not sure if it's the same thing. Other Z-Wave devices that I also set to report basic and meter changes do not have this duplicated report issue.

Under Programs, Zwave I see 5 items, 4 of which are running:

I just stopped all of them and still getting double reports every 10 seconds.

genemars commented 1 year ago

Do the same on each hg connected to mqtt.

EnGamma commented 1 year ago

There is only one instance of HG running.

genemars commented 1 year ago

There's no apparent reason for the device to send that report twice unless it is misconfigured and at this point the issue should persist also with HG 1.3

This is one of my Z-Wave device, no dupes. It is a dimmer with meter configured to report every 30 seconds.

Screenshot_20230302-215719161.jpg

Also on my other pi with a different Z-Wave dongle and different devices I never seen this issue.