Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log Entry Duplication [BUG] #454

Closed
EnGamma opened this issue Jan 12, 2023 · 12 comments
Closed

Log Entry Duplication [BUG] #454

EnGamma opened this issue Jan 12, 2023 · 12 comments
Labels
bug

Comments

@EnGamma
Copy link

EnGamma commented Jan 12, 2023

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
@EnGamma EnGamma added the bug label Jan 12, 2023
@genemars
Copy link
Member

genemars commented Mar 1, 2023

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
Copy link
Author

EnGamma commented Mar 2, 2023 •
edited
Loading

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
Copy link
Author

EnGamma commented Mar 2, 2023 •
edited
Loading

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
Copy link
Member

genemars commented Mar 2, 2023

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
Copy link
Author

EnGamma commented Mar 2, 2023 •
edited
Loading

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
Copy link
Author

EnGamma commented Mar 2, 2023 •
edited
Loading

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
Copy link
Author

EnGamma commented Mar 2, 2023

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
Copy link
Member

genemars commented Mar 2, 2023

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
Copy link
Author

EnGamma commented Mar 2, 2023

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:

  • level poll
  • meter watt poll
  • multi-instance/channel virtual modules
  • query on wake-up
    x zwave thermostat poll

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

@genemars
Copy link
Member

genemars commented Mar 2, 2023

Do the same on each hg connected to mqtt.

@EnGamma
Copy link
Author

EnGamma commented Mar 2, 2023

There is only one instance of HG running.

@genemars
Copy link
Member

genemars commented Mar 2, 2023

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@genemars @EnGamma