search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
912 stars 420 forks source link

InfluxDB persistence not recording all events #3161

Closed bassmaster187 closed 1 year ago

bassmaster187 commented 1 year ago

It seems like InfluxDB persistence is not recording all received events from MQTT.

I can see all events are in events.log but many of them are missing in InfluxDB.

    76958   2022-11-11 09:35:58.232 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 707 to 708
    76973   2022-11-11 09:36:28.242 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 708 to 707
    76989   2022-11-11 09:36:58.250 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 707 to 705
    77005   2022-11-11 09:37:28.223 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 705 to 704
    77019   2022-11-11 09:37:58.261 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 704 to 705
    77038   2022-11-11 09:38:28.264 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 705 to 706
    77058   2022-11-11 09:38:58.252 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 706 to 705
    77076   2022-11-11 09:39:28.272 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 705 to 704
    77097   2022-11-11 09:39:58.272 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 704 to 697
    77111   2022-11-11 09:40:28.231 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 697 to 702
    77135   2022-11-11 09:40:58.232 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 702 to 709
    77152   2022-11-11 09:41:28.233 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 709 to 705
    77167   2022-11-11 09:41:58.281 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 705 to 701
    77188   2022-11-11 09:42:28.285 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 701 to 699
    77209   2022-11-11 09:42:58.251 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 699 to 698
    77225   2022-11-11 09:43:28.262 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 698 to 696
    77241   2022-11-11 09:43:58.242 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 696 to 702
    77259   2022-11-11 09:44:28.262 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 702 to 700
    77276   2022-11-11 09:44:58.271 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 700 to 699
    77293   2022-11-11 09:45:28.271 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 699 to 697
    77317   2022-11-11 09:45:58.272 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 697 to 2

In the InfluxDB is just one single event:

image

It is not always that bad:

    85549   2022-11-11 16:40:29.344 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 697 to 695
    85573   2022-11-11 16:40:59.345 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 695 to 691
    85588   2022-11-11 16:41:29.304 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 691 to 689
    85608   2022-11-11 16:41:59.335 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 689 to 691
    85624   2022-11-11 16:42:29.294 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 691 to 694
    85667   2022-11-11 16:43:29.304 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 694 to 685
    85683   2022-11-11 16:43:59.304 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 685 to 684
    85704   2022-11-11 16:44:29.334 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 684 to 687
    85721   2022-11-11 16:44:59.354 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 687 to 686
    85738   2022-11-11 16:45:29.315 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 686 to 689
    85751   2022-11-11 16:45:59.326 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 689 to 690
    85794   2022-11-11 16:46:59.315 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 690 to 686
    85813   2022-11-11 16:47:29.295 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 686 to 687
    85848   2022-11-11 16:48:29.313 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 687 to 695
    85867   2022-11-11 16:48:59.357 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 695 to 703
    85893   2022-11-11 16:49:29.344 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 703 to 692
    85916   2022-11-11 16:49:59.354 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 692 to 690
    85929   2022-11-11 16:50:29.336 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'MQTTSoyo_SoyoWatt' changed from 690 to 691

During the same period just 8 events are missing:

openhab.log is empty for the whole day.

this is my influxdb.persist file:

Strategies {
    everyMinute : "0 * * * * ?"
    everyHour   : "0 0 * * * ?"
    everyDay    : "0 0 0 * * ?"
    default = everyChange, restoreOnStartup
}

Items {
    everyMinutePersistance*             : strategy = everyMinute, restoreOnStartup
    everyHourPersistance*               : strategy = everyHour, restoreOnStartup
    everyDayPersistance*               : strategy = everyHour, restoreOnStartup
    jkbms_jkbmsstateofcharge            : strategy = everyChange, everyHour, restoreOnStartup
    *                                   : strategy = everyChange, restoreOnStartup
}

Openhab3 is running an Synology / Docker Version 3.3.0 InfluxDB is running on same machin (Synology / Docker) Version 2.4 My Synology has got 6GB of free RAM / CPU hat an avg of 10% I have like 2000 event changes per hour / 33 events per minute

To make sure it isn't a performance problem, I made a dotnet c# script inserting data in influxdb (OpenHab is not involved) and thats absolutely reliable. So the Problem must be anywhere in OpenHab3.

In OpenHab events.log we can see 19 events received:

    88135   2022-11-11 17:55:28.132 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -654.97 to -641.16
    88146   2022-11-11 17:55:43.388 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -641.16 to -641.14
    88156   2022-11-11 17:55:58.586 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -641.14 to -640.58
    88163   2022-11-11 17:56:13.821 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -640.58 to -631.52
    88172   2022-11-11 17:56:29.063 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -631.52 to -649.74
    88180   2022-11-11 17:56:44.317 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -649.74 to -635.72
    88192   2022-11-11 17:56:59.576 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -635.72 to -644.70
    88201   2022-11-11 17:57:14.762 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -644.70 to -644.34
    88212   2022-11-11 17:57:30.030 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -644.34 to -644.03
    88216   2022-11-11 17:57:45.258 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -644.03 to -635.01
    88228   2022-11-11 17:58:00.509 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -635.01 to -634.68
    88232   2022-11-11 17:58:15.774 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -634.68 to -634.66
    88241   2022-11-11 17:58:30.964 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -634.66 to -634.33
    88248   2022-11-11 17:58:46.202 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -634.33 to -634.40
    88260   2022-11-11 17:59:01.448 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -634.40 to -638.82
    88268   2022-11-11 17:59:16.691 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -638.82 to -638.54
    88277   2022-11-11 17:59:31.956 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -638.54 to -642.90
    88284   2022-11-11 17:59:47.204 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -642.90 to -642.95
    88301   2022-11-11 18:00:02.408 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'jkbms_jkbmspower' changed from -642.95 to -638.11

My dotnet application has successfully inserted 19 values but OpenHab inserted only 2 values:

image

So we can say:

J-N-K commented 1 year ago

Can you please do log:set TRACE org.openhab.persistence.influxdb.InfluxDBPersistenceService on the Karaf console and check if you see one of these messages for each datapoint:

You can later reset the logging with log:set DEFAULT org.openhab.persistence.influxdb.InfluxDBPersistenceService

bassmaster187 commented 1 year ago 
09:25:52.143 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Production' changed from 2.42 kW to 3.43 kW
09:25:52.146 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Consumption' changed from 3.5 kW to 2.01 kW
09:25:52.147 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Export' changed from 0 kW to 1.42 kW
09:25:52.148 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Import' changed from 1.08 kW to 0 kW
09:25:52.452 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 2.959 to 2.968
09:25:52.456 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsdeltacellvoltage' changed from 0.029 to 0.031
09:25:52.458 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 23.67 to 23.75
09:25:52.460 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 266.78 to 518.02
09:25:52.462 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmscurrent' changed from 11.27 to 21.82
09:25:52.463 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 266.78 to 518.02
09:25:57.248 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausHeute' changed from 0.068 to 0.069
09:25:57.249 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausWatt' changed from 83 to 81
09:26:01.171 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MPPSolarCurrData_MPPSolarChannel' changed from 167 to 190
09:26:07.695 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsdeltacellvoltage' changed from 0.031 to 0.029
09:26:07.697 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 2.968 to 2.990
09:26:07.699 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 23.75 to 23.92
09:26:07.703 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmscurrent' changed from 21.82 to 56.72
09:26:07.705 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 518.02 to 1356.77
09:26:07.708 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 518.02 to 1356.77
09:26:15.241 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BWatt' changed from 524 to 816
09:26:15.243 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BHeute' changed from 0.002 to 0.008
09:26:15.245 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BTotal' changed from 15.5 to 15.506
09:26:20.338 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Watt' changed from 0 to 903
09:26:20.340 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Total' changed from 67.602 to 67.606
09:26:20.341 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Heute' changed from 0 to 0.005
09:26:21.940 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MotionSensorTreppeCentraLite_LetzteAktualisierung' changed from 2022-11-15T09:21:21.772+0100 to 2022-11-15T09:26:21.928+0100
09:26:22.952 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsdeltacellvoltage' changed from 0.029 to 0.026
09:26:22.954 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 2.990 to 3.002
09:26:22.955 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmscurrent' changed from 56.72 to 56.54
09:26:22.956 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 23.92 to 24.01
09:26:22.958 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 1356.77 to 1357.61
09:26:22.959 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 1356.77 to 1357.61
09:26:27.233 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausTotal' changed from 256.959 to 256.96
09:26:27.234 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausWatt' changed from 81 to 84
09:26:31.171 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MPPSolarCurrData_MPPSolarChannel' changed from 190 to 172
09:26:38.137 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 3.002 to 3.011
09:26:38.138 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspowertubetemperature' changed from 21 to 22
09:26:38.139 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 1357.61 to 1361.74
09:26:38.140 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 24.01 to 24.09
09:26:38.143 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 1357.61 to 1361.74
09:26:45.100 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MotionSensorTreppeCentraLite_Bewegung_LetzteAktualisierung' changed from 2022-11-15T09:25:20.094+0100 to 2022-11-15T09:26:45.100+0100
09:26:45.245 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BWatt' changed from 816 to 820
09:26:45.246 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BHeute' changed from 0.008 to 0.015
09:26:45.248 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BTotal' changed from 15.506 to 15.513
09:26:47.365 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Production_day' changed from 1.379 kWh to 1.585 kWh
09:26:50.341 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Watt' changed from 903 to 904
09:26:50.343 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Total' changed from 67.606 to 67.614
09:26:50.344 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Heute' changed from 0.005 to 0.012
09:26:53.400 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsdeltacellvoltage' changed from 0.026 to 0.024
09:26:53.402 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 3.011 to 3.020
09:26:53.404 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 1361.74 to 1365.76
09:26:53.405 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 24.09 to 24.16
09:26:53.406 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 1361.74 to 1365.76
09:26:57.224 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausTotal' changed from 256.96 to 256.961
09:26:57.225 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausHeute' changed from 0.069 to 0.07
09:26:57.226 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausWatt' changed from 84 to 76
09:27:01.171 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MPPSolarCurrData_MPPSolarChannel' changed from 172 to 167
09:27:07.154 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Production' changed from 3.43 kW to 3.21 kW
09:27:07.155 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Consumption' changed from 2.01 kW to 3.09 kW
09:27:07.156 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'SolarEdge_Export' changed from 1.42 kW to 0.12 kW
09:27:08.647 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsdeltacellvoltage' changed from 0.024 to 0.025
09:27:08.649 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 1365.76 to 1369.04
09:27:08.650 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 3.020 to 3.027
09:27:08.652 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 24.16 to 24.21
09:27:08.653 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 1365.76 to 1369.04
09:27:15.244 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BWatt' changed from 820 to 822
09:27:15.246 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BHeute' changed from 0.015 to 0.022
09:27:15.248 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BTotal' changed from 15.513 to 15.52
09:27:20.335 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Total' changed from 67.614 to 67.621
09:27:20.336 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1_Charger1Heute' changed from 0.012 to 0.02
09:27:23.882 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsdeltacellvoltage' changed from 0.025 to 0.022
09:27:23.884 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 1369.04 to 1367.64
09:27:23.887 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmscurrent' changed from 56.54 to 56.36
09:27:23.889 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 3.027 to 3.033
09:27:23.894 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 24.21 to 24.27
09:27:23.896 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 1369.04 to 1367.64
09:27:27.227 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausHeute' changed from 0.07 to 0.071
09:27:27.229 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'PVSpielhausWatt' changed from 76 to 82
09:27:31.172 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MPPSolarCurrData_MPPSolarChannel' changed from 167 to 170
09:27:39.138 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmsaveragecellvoltage' changed from 3.033 to 3.040
09:27:39.141 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmstotalvoltage' changed from 24.27 to 24.32
09:27:39.144 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmspower' changed from 1367.64 to 1370.57
09:27:39.148 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'jkbms_jkbmschargingpower' changed from 1367.64 to 1370.57
09:27:45.243 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BWatt' changed from 822 to 825
09:27:45.244 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BHeute' changed from 0.022 to 0.029
09:27:45.246 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'MQTTCharger1B_Charger1BTotal' changed from 15.52 to 15.527
09:27:46.192 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item jkbms_jkbmsaveragecellvoltage (Type=NumberItem, State=3.040, Label=jk-bms average cell voltage, Category=, Tags=[Measurement, Voltage], Groups=[PV, everyMinutePersistance]) in InfluxDB point InfluxPoint{measurementName='jkbms_jkbmsaveragecellvoltage', time=2022-11-15T08:27:46.192527Z, value=3.040, tags={item=jkbms_jkbmsaveragecellvoltage}}
09:27:46.194 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item jkbms_jkbmsdeltacellvoltage (Type=NumberItem, State=0.022, Label=jk-bms delta cell voltage, Category=, Tags=[Point], Groups=[everyMinutePersistance]) in InfluxDB point InfluxPoint{measurementName='jkbms_jkbmsdeltacellvoltage', time=2022-11-15T08:27:46.194530Z, value=0.022, tags={item=jkbms_jkbmsdeltacellvoltage}}
09:27:46.197 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item jkbms_jkbmstotalvoltage (Type=NumberItem, State=24.32, Label=jk-bms total voltage, Category=, Tags=[Measurement, Voltage], Groups=[PV, everyMinutePersistance]) in InfluxDB point InfluxPoint{measurementName='jkbms_jkbmstotalvoltage', time=2022-11-15T08:27:46.197305Z, value=24.32, tags={item=jkbms_jkbmstotalvoltage}}
09:27:47.660 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Gabelstaplerbatterie' changed from OFF to ON
09:27:49.068 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item PVSpielhausHeute (Type=NumberItem, State=0.071, Label=PVSpielhaus Heute, Category=, Tags=[Measurement, Energy], Groups=[PV]) in InfluxDB point InfluxPoint{measurementName='PVSpielhausHeute', time=2022-11-15T08:27:49.068523Z, value=0.071, tags={item=PVSpielhausHeute}}
09:27:49.072 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item jkbms_jkbmsaveragecellvoltage (Type=NumberItem, State=3.040, Label=jk-bms average cell voltage, Category=, Tags=[Measurement, Voltage], Groups=[PV, everyMinutePersistance]) in InfluxDB point InfluxPoint{measurementName='jkbms_jkbmsaveragecellvoltage', time=2022-11-15T08:27:49.071665Z, value=3.040, tags={item=jkbms_jkbmsaveragecellvoltage}}
09:27:49.073 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item jkbms_jkbmsdeltacellvoltage (Type=NumberItem, State=0.022, Label=jk-bms delta cell voltage, Category=, Tags=[Point], Groups=[everyMinutePersistance]) in InfluxDB point InfluxPoint{measurementName='jkbms_jkbmsdeltacellvoltage', time=2022-11-15T08:27:49.073427Z, value=0.022, tags={item=jkbms_jkbmsdeltacellvoltage}}
09:27:49.081 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item jkbms_jkbmstotalvoltage (Type=NumberItem, State=24.32, Label=jk-bms total voltage, Category=, Tags=[Measurement, Voltage], Groups=[PV, everyMinutePersistance]) in InfluxDB point InfluxPoint{measurementName='jkbms_jkbmstotalvoltage', time=2022-11-15T08:27:49.081321Z, value=24.32, tags={item=jkbms_jkbmstotalvoltage}}
bassmaster187 commented 1 year ago

I have 40 event changes in one minute, but only 8 "Storing items" at the same minute.

J-N-K commented 1 year ago

That looks like a bug. Can you please show the definition of at least two items that are affected (including the definition of all groups the items are in). I'll try to reproduce that on my development system.

Do you have any other persistence service configured?

bassmaster187 commented 1 year ago

It seems like pretty much all MQTT Items are affected. If Items of other things like decons are affected I'm not sure. Anyway, here are two items:

No other persistance service configured.

Let me know if you need more infos. Thanks.

J-N-K commented 1 year ago

I meant the real item definition (either from the file or a screenshot from the "Edit item" page), for both the item and all groups. Or you can send the *.items file(s) or the org.openhab.core.items.Item.json file from userdata/jsondb to github@klug.nrw.

Regarding the log above: How long did you wait after changing the log-level to get that log?

bassmaster187 commented 1 year ago

image

image

image

bassmaster187 commented 1 year ago

Regarding the log above: How long did you wait after changing the log-level to get that log?

one hour

J-N-K commented 1 year ago

I cannot reproduce that. I have even created 60 events per second for three items and every single one arrives at the persistence service:

20:22:40.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem1' changed from 212.24 to 212.25
20:22:40.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.25, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:40.851685Z, value=212.25, tags={item=NewItem1}}
20:22:40.852 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem2' changed from 424.48 to 424.50
20:22:40.852 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem3' changed from 636.72 to 636.75
20:22:40.852 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.25, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:40.852607Z, value=212.25, tags={item=NewItem1}}
20:22:40.852 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem3 (Type=StringItem, State=636.75, Label=New Item, Category=, Groups=[PV]) in InfluxDB point InfluxPoint{measurementName='NewItem3', time=2022-11-18T19:22:40.852785Z, value=636.75, tags={item=NewItem3}}
20:22:40.852 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem2 (Type=NumberItem, State=424.50, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem2', time=2022-11-18T19:22:40.852915Z, value=424.50, tags={item=NewItem2}}
20:22:41.846 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.26, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:41.846437Z, value=212.26, tags={item=NewItem1}}
20:22:41.846 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem1' changed from 212.25 to 212.26
20:22:41.846 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem2' changed from 424.50 to 424.52
20:22:41.846 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.26, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:41.846741Z, value=212.26, tags={item=NewItem1}}
20:22:41.846 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem3' changed from 636.75 to 636.78
20:22:41.846 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem3 (Type=StringItem, State=636.78, Label=New Item, Category=, Groups=[PV]) in InfluxDB point InfluxPoint{measurementName='NewItem3', time=2022-11-18T19:22:41.846920Z, value=636.78, tags={item=NewItem3}}
20:22:41.847 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem2 (Type=NumberItem, State=424.52, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem2', time=2022-11-18T19:22:41.847037Z, value=424.52, tags={item=NewItem2}}
20:22:42.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem1' changed from 212.26 to 212.27
20:22:42.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.27, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:42.851829Z, value=212.27, tags={item=NewItem1}}
20:22:42.852 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem2' changed from 424.52 to 424.54
20:22:42.852 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.27, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:42.852203Z, value=212.27, tags={item=NewItem1}}
20:22:42.852 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem3' changed from 636.78 to 636.81
20:22:42.852 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem3 (Type=StringItem, State=636.81, Label=New Item, Category=, Groups=[PV]) in InfluxDB point InfluxPoint{measurementName='NewItem3', time=2022-11-18T19:22:42.852469Z, value=636.81, tags={item=NewItem3}}
20:22:42.852 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem2 (Type=NumberItem, State=424.54, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem2', time=2022-11-18T19:22:42.852583Z, value=424.54, tags={item=NewItem2}}
20:22:43.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem1' changed from 212.27 to 212.28
20:22:43.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.28, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:43.851078Z, value=212.28, tags={item=NewItem1}}
20:22:43.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem2' changed from 424.54 to 424.56
20:22:43.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem3' changed from 636.81 to 636.84
20:22:43.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.28, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:43.851497Z, value=212.28, tags={item=NewItem1}}
20:22:43.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem3 (Type=StringItem, State=636.84, Label=New Item, Category=, Groups=[PV]) in InfluxDB point InfluxPoint{measurementName='NewItem3', time=2022-11-18T19:22:43.851678Z, value=636.84, tags={item=NewItem3}}
20:22:43.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem2 (Type=NumberItem, State=424.56, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem2', time=2022-11-18T19:22:43.851787Z, value=424.56, tags={item=NewItem2}}
20:22:44.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.29, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:44.851016Z, value=212.29, tags={item=NewItem1}}
20:22:44.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem1' changed from 212.28 to 212.29
20:22:44.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem1 (Type=NumberItem, State=212.29, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem1', time=2022-11-18T19:22:44.851317Z, value=212.29, tags={item=NewItem1}}
20:22:44.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem2' changed from 424.56 to 424.58
20:22:44.851 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'NewItem3' changed from 636.84 to 636.87
20:22:44.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem3 (Type=StringItem, State=636.87, Label=New Item, Category=, Groups=[PV]) in InfluxDB point InfluxPoint{measurementName='NewItem3', time=2022-11-18T19:22:44.851523Z, value=636.87, tags={item=NewItem3}}
20:22:44.851 [TRACE] [e.influxdb.InfluxDBPersistenceService] - Storing item NewItem2 (Type=NumberItem, State=424.58, Label=New Item, Category=, Groups=[everyMinutePersistance, PV]) in InfluxDB point InfluxPoint{measurementName='NewItem2', time=2022-11-18T19:22:44.851687Z, value=424.58, tags={item=NewItem2}}

There must be something special in your setup. I also tried with your item name, but that doesn't make any difference.

bassmaster187 commented 1 year ago

I'm not the only one with this problem: https://community.openhab.org/t/persistence-not-recording-all-events/139300

J-N-K commented 1 year ago

Can you please try 

update org.openhab.core.persistence https://janessa.me/esh/org.openhab.core.persistence-3.4.0-SNAPSHOT.jar

restart openHAB and then log:set TRACE org.openhab.core.persistence? You don't need to set the log-level for the influxdb persistence service itself, it seems that is the problem. Technically this is the same bundle like before, just a little bit more logging to check what's going wrong.

If you want to revert to the original bundle, you can just install/uninstall any add-on.

lolodomo commented 1 year ago

That issue should be moved to addons repo,

J-N-K commented 1 year ago

No. This is most likely a core issue as similar issues are reported with JDBC (see the linked forum post).

bassmaster187 commented 1 year ago

@J-N-K it seems now after updating your jar file now nothing works anymore. I have hundreds of "could not resove module" in logfile. For instance:


2022-11-21 15:13:35.850 [ERROR] [Events.Framework                    ] - FrameworkEvent ERROR
org.osgi.framework.BundleException: Could not resolve module: org.openhab.core.addon.marketplace [149]
  Unresolved requirement: Import-Package: org.openhab.core.ui.components; version="[3.3.0,4.0.0)"
    -> Export-Package: org.openhab.core.ui.components; bundle-symbolic-name="org.openhab.core.ui"; bundle-version="3.3.0"; version="3.3.0"; uses:="org.openhab.core.common.registry,org.openhab.core.config.core.dto"
       org.openhab.core.ui [213]
         Unresolved requirement: Import-Package: de.erichseifert.vectorgraphics2d; resolution:="optional"
         Unresolved requirement: Import-Package: org.openhab.core.persistence; version="[3.3.0,4.0.0)"
           -> Export-Package: org.openhab.core.persistence; bundle-symbolic-name="org.openhab.core.persistence"; bundle-version="3.4.0.202211190858"; version="3.4.0"; uses:="org.openhab.core.items,org.openhab.core.persistence.config,org.openhab.core.persistence.strategy,org.openhab.core.types"
              org.openhab.core.persistence [207]
                Unresolved requirement: Import-Package: org.openhab.core.common; version="[3.4.0,4.0.0)"

    at org.eclipse.osgi.container.Module.start(Module.java:463) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1783) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) ~[org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) [org.eclipse.osgi-3.17.200.jar:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345) [org.eclipse.osgi-3.17.200.jar:?]

Openhab GUI doesn't start anymore.

bassmaster187 commented 1 year ago

OpenHab is now starting again with: update org.openhab.core.persistence mvn:org.openhab.core.bundles/org.openhab.core.persistence/3.3.0

J-N-K commented 1 year ago

Oops. Sorry, that's my fault. Can you try again with 

update org.openhab.core.persistence https://janessa.me/esh/org.openhab.core.persistence-3.3.0-SNAPSHOT.jar

If it doesn't work: The way you got back is a good choice. But remember that you may need to restart for all bundles to resolve properly after updating.

bassmaster187 commented 1 year ago

Thanks.

For any reason it seams like rrd4j persistance is on. I'll check it. I checked some items and it seams like all values are in influxdb. Let's wait a couple of hours. 

2022-11-21 17:51:18.093 [TRACE] [persistence.internal.PersistItemsJob] - Storing item 'everyMinutePersistance' with persistence service 'rrd4j' took 0ms
2022-11-21 17:51:18.181 [TRACE] [persistence.internal.PersistItemsJob] - Storing item 'LichterketteWohnzimmerMLI_Farbe' with persistence service 'rrd4j' took 87ms
2022-11-21 17:51:18.183 [TRACE] [persistence.internal.PersistItemsJob] - Storing item 'everyDayPersistance' with persistence service 'rrd4j' took 0ms
2022-11-21 17:51:18.259 [TRACE] [persistence.internal.PersistItemsJob] - Storing item 'Garagentor_OffenGeschlossen' with persistence service 'rrd4j' took 75ms
2022-11-21 17:51:18.347 [TRACE] [persistence.internal.PersistItemsJob] - Storing item 'PVSpielhausTotal' with persistence service 'rrd4j' took 86ms
2022-11-21 17:51:18.426 [TRACE] [persistence.internal.PersistItemsJob] - Storing item 'jkbms_jkbmstotalvoltage' with persistence service 'rrd4j' took 78ms

hmm, RRD4j persistence is off...

image

J-N-K commented 1 year ago

That's very astonishing, because all that changed in the version I provided is some additional logging.

bassmaster187 commented 1 year ago

Should I unistall it? https://community.openhab.org/t/is-there-a-way-to-disable-rrd4j-completely/135560

J-N-K commented 1 year ago

The configuration is not for enabling/disabling persistence services (this is done by installung/uninstall the service from the add-ons page) but for selecting the default service. If you don't want to use rrd4j, I would recommend to uninstall it.

bassmaster187 commented 1 year ago

As far as I can see, deinstalling RRD4j persistance solve the problem: image

With RRD4j 3 days ago: image

J-N-K commented 1 year ago

It seems we can't find out what the issue is. I still don't understand what might happen.