Closed saruter closed 3 years ago
Hey there @adamchengtkc, @janiversen, @vzahradnik, mind taking a look at this issue as its been labeled with an integration (modbus
) you are listed as a codeowner for? Thanks!
(message by CodeOwnersMention)
@janiversen did you change something related to Sensors in recent releases? My only change since April is the Cover
code, which was not yet released in stable builds. It is possible the bug was there also in earlier releases.
@vzahradnik not that I know, but this might be a very old bug.
I can see 2 problems: 1) state is read before update is called, that would produce a random number for the first read. 2) state is not saved so after a restart it will be wrong until update is called.
However I cannot see a reason why it stays wrong until HA is restarted but when I look at the supplied chart the wrong value is only present for one interval.
It is more likely a problem in the modbus communication.
@saruter can you please run it with debug (as pr documentation) and supply the log. Does it also happen if only have 1-2 sensors ?
I will try to see how I can test the points I made.
I did a little more digging into this issue from my side. It seems that the values of sensors are swapped, so values from one sensor are written to another sensor. You can see it in the following graph made from different temperature sensors of my heating system (Data from HA visualizied via Prometheus and Grafana). After a problematic restart of HA it seems that for example the "Aussentemperatur" value is displayed in the "Heizungspuffer unten" sensor (14.5°C). After another restart of HA every value is recorded in the correct sensor. I am polling some registers more often than others (30s vs. 300s), could that be a issue when starting the integration? But it was working fine for months... First issue was encountered after a restart on 20.08.2020 (looked back in Prometheus data). On that day I updated HA to version 0.114.2. Probably this could help.
Hmmmm first thanks for digging, that sounds like a serious problem. However the integration as such do not hold an array of sensor states, a swap can basically only happen in 2 places:
1) in the core module calling the integration, this seems very unlikely. 2) in the modbus communication (pymodbus and device), which seems more likely.
We really need some debug logs, to determine if the device makes the swap or the swap happens in the pymodbus stack. It would also be nice to know if it happens with a minimal configuration something like 4 or 6 sensors.
Hi, I could't reproduce the issue when restarting just restarting HA (tried it 10 times I think), but after a complete reboot of the HassOS (the VM) the issue occured at first try. If I remember correctly it occured mostly when restarting the whole System but I'm not really sure. I have attached debug logs which I have reduced from log-entries not relevant of the issue (mostly other integrations). But you can see when the issue occurs.
Hopefully you can find a clue whats going on here...
Some examples: Sensor "Aussentemperatur" which swaps values with "Heizungspuffer unten"
2020-10-02 15:54:08 DEBUG (SyncWorker_30) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2020-10-02 15:54:08 DEBUG (SyncWorker_30) [pymodbus.transaction] Running transaction 5
2020-10-02 15:54:08 DEBUG (SyncWorker_30) [pymodbus.transaction] SEND: 0x0 0x5 0x0 0x0 0x0 0x6 0x1 0x4 0x81 0x9 0x0 0x1
2020-10-02 15:54:08 DEBUG (SyncWorker_30) [pymodbus.client.sync] New Transaction state 'SENDING'
2020-10-02 15:54:08 DEBUG (SyncWorker_30) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.transaction] Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.transaction] RECV: 0x0 0x4 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x1 0xd6
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.framer.socket_framer] Processing: 0x0 0x4 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x1 0xd6
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.factory] Factory Response[ReadInputRegistersResponse: 4]
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.transaction] Adding transaction 5
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.transaction] Getting transaction 5
2020-10-02 15:54:09 DEBUG (SyncWorker_30) [pymodbus.transaction] Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2020-10-02 15:54:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.aussentemperatur, old_state=<state sensor.aussentemperatur=17.50; unit_of_measurement=°C, friendly_name=Aussentemperatur @ 2020-10-02T15:53:37.166673+02:00>, new_state=<state sensor.aussentemperatur=47.00; unit_of_measurement=°C, friendly_name=Aussentemperatur @ 2020-10-02T15:54:09.242506+02:00>>
2020-10-02 15:54:09 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481352036064] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.aussentemperatur, old_state=<state sensor.aussentemperatur=17.50; unit_of_measurement=°C, friendly_name=Aussentemperatur @ 2020-10-02T15:53:37.166673+02:00>, new_state=<state sensor.aussentemperatur=47.00; unit_of_measurement=°C, friendly_name=Aussentemperatur @ 2020-10-02T15:54:09.242506+02:00>>}
2020-10-02 15:54:09 DEBUG (SyncWorker_50) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
Or sensor "Brennerleistung" which suddenly gets a value of 451.70 (raw value 4517) which is the value of sensor "Brennerstarts"
2020-10-02 15:54:12 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481294046976] Sending {'id': 14, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.brennerstarts, old_state=<state sensor.brennerstarts=4517; unit_of_measurement=Starts, friendly_name=Brennerstarts, icon=mdi:fire @ 2020-10-02T15:53:37.171807+02:00>, new_state=<state sensor.brennerstarts=4255; unit_of_measurement=Starts, friendly_name=Brennerstarts, icon=mdi:fire @ 2020-10-02T15:54:12.247237+02:00>>}
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.transaction] Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.transaction] RECV: 0x0 0xb 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x11 0xa5
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.framer.socket_framer] Processing: 0x0 0xb 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x11 0xa5
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.factory] Factory Response[ReadInputRegistersResponse: 4]
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.transaction] Adding transaction 12
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.transaction] Getting transaction 12
2020-10-02 15:54:12 DEBUG (SyncWorker_59) [pymodbus.transaction] Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2020-10-02 15:54:12 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.brennerleistung, old_state=<state sensor.brennerleistung=0.00; unit_of_measurement=kW, friendly_name=Brennerleistung, icon=mdi:speedometer @ 2020-10-02T15:53:37.172006+02:00>, new_state=<state sensor.brennerleistung=451.70; unit_of_measurement=kW, friendly_name=Brennerleistung, icon=mdi:speedometer @ 2020-10-02T15:54:12.743688+02:00>>
2020-10-02 15:54:12 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481352036064] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.brennerleistung, old_state=<state sensor.brennerleistung=0.00; unit_of_measurement=kW, friendly_name=Brennerleistung, icon=mdi:speedometer @ 2020-10-02T15:53:37.172006+02:00>, new_state=<state sensor.brennerleistung=451.70; unit_of_measurement=kW, friendly_name=Brennerleistung, icon=mdi:speedometer @ 2020-10-02T15:54:12.743688+02:00>>}
2020-10-02 15:54:12 DEBUG (SyncWorker_32) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2020-10-02 15:54:12 DEBUG (SyncWorker_32) [pymodbus.transaction] Running transaction 13
2020-10-02 15:54:12 DEBUG (SyncWorker_32) [pymodbus.transaction] SEND: 0x0 0xd 0x0 0x0 0x0 0x6 0x1 0x4 0x83 0x4 0x0 0x1
2020-10-02 15:54:12 DEBUG (SyncWorker_32) [pymodbus.client.sync] New Transaction state 'SENDING'
2020-10-02 15:54:12 DEBUG (SyncWorker_32) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2020-10-02 15:54:12 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481294046976] Sending {'id': 14, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.brennerleistung, old_state=<state sensor.brennerleistung=0.00; unit_of_measurement=kW, friendly_name=Brennerleistung, icon=mdi:speedometer @ 2020-10-02T15:53:37.172006+02:00>, new_state=<state sensor.brennerleistung=451.70; unit_of_measurement=kW, friendly_name=Brennerleistung, icon=mdi:speedometer @ 2020-10-02T15:54:12.743688+02:00>>}
2020-10-02 15:54:13 DEBUG (MainThread) [homeassistant.components.wled] Finished fetching wled data in 0.016 seconds
Sensor "heizungspuffertemperatur_oben" shows values of Sensor "Speicherreferenztemperatur"
At Home Assistant Start:
2020-10-02 15:53:37 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.heizungspuffertemperatur_oben, old_state=None, new_state=<state sensor.heizungspuffertemperatur_oben=47.50; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:53:37.166382+02:00>>
Then update via modbus with wrong value:
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] Running transaction 4
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] SEND: 0x0 0x4 0x0 0x0 0x0 0x6 0x1 0x4 0x81 0x3 0x0 0x1
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.client.sync] New Transaction state 'SENDING'
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2020-10-02 15:54:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481352036064] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.speicherreferenztemperatur, old_state=<state sensor.speicherreferenztemperatur=24.70; unit_of_measurement=°C, friendly_name=Speicherreferenztemperatur @ 2020-10-02T15:53:37.166087+02:00>, new_state=<state sensor.speicherreferenztemperatur=32.70; unit_of_measurement=°C, friendly_name=Speicherreferenztemperatur @ 2020-10-02T15:54:08.247846+02:00>>}
2020-10-02 15:54:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481294046976] Sending {'id': 14, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.speicherreferenztemperatur, old_state=<state sensor.speicherreferenztemperatur=24.70; unit_of_measurement=°C, friendly_name=Speicherreferenztemperatur @ 2020-10-02T15:53:37.166087+02:00>, new_state=<state sensor.speicherreferenztemperatur=32.70; unit_of_measurement=°C, friendly_name=Speicherreferenztemperatur @ 2020-10-02T15:54:08.247846+02:00>>}
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] RECV: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xf7
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.framer.socket_framer] Processing: 0x0 0x3 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xf7
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.factory] Factory Response[ReadInputRegistersResponse: 4]
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] Adding transaction 4
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] Getting transaction 4
2020-10-02 15:54:08 DEBUG (SyncWorker_2) [pymodbus.transaction] Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2020-10-02 15:54:08 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.heizungspuffertemperatur_oben, old_state=<state sensor.heizungspuffertemperatur_oben=47.50; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:53:37.166382+02:00>, new_state=<state sensor.heizungspuffertemperatur_oben=24.70; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:54:08.745052+02:00>>
2020-10-02 15:54:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481352036064] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.heizungspuffertemperatur_oben, old_state=<state sensor.heizungspuffertemperatur_oben=47.50; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:53:37.166382+02:00>, new_state=<state sensor.heizungspuffertemperatur_oben=24.70; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:54:08.745052+02:00>>}
2020-10-02 15:54:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.140481294046976] Sending {'id': 14, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.heizungspuffertemperatur_oben, old_state=<state sensor.heizungspuffertemperatur_oben=47.50; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:53:37.166382+02:00>, new_state=<state sensor.heizungspuffertemperatur_oben=24.70; unit_of_measurement=°C, friendly_name=Heizungspuffertemperatur oben @ 2020-10-02T15:54:08.745052+02:00>>}
Thanks a lot, this seems to be just what I need to isolate the problem. I will analyze it this weekend, and let you know what I find. I assume I can the configuration for the sensors in error in the configuration you supplied, please let me know if you changed anything.
Hi, i did not change configuration besides turning on debugging. Thanks for looking into that...
Have tested this problem further, but I am not able to reproduce it, nor can I see where values can get mixed in our code.
However this Issue was just raised in pymodbus: https://github.com/riptideio/pymodbus/issues/538 Previous response from modbus device returned as current response when using sync TCP over network with lag
This sounds a lot like the same problem. Once I see a PR (in pymodbus) to solve this I will test again.
There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.
Issue is still present.
In that case, please make a small example (that we can easier simulate) with max 1-2 devices. Provide the config, the log and what values you expected. Since I currently cannot reproduce the problem, I cannot help without more information.
There is one racing situation we cannot control, when HA starts up it ask the modbus integration to configure itself, while doing that most values (not the custom ones) will be set to the last known value, and shortly after the device will be called to get the real current values. This can explain a major jump in value, but not the peak I see in the graph.
Please update to newest version (as soon as it becomes available), as we have made quite a number of changes on dev among other the startup priorities. With a bit of luck we have solved your issue too.
version 2021.4.0 will be available in a day or two, and could very well have solved your issue.
PR 49052 is issued, awaiting review and merge, which solves your problem as far as I have been able to reproduce it.
Great news, I will update soon.... Thanks for all the hard work!
The problem
After restart of Home Assistant some values of Modbus registers show wrong values. Only solution is to restart Home Assistant again then it is working fine most of the time
Environment
Problem-relevant
configuration.yaml
Traceback/Error logs
Additional information
Starting in Home Assistant 0.114 (I think) sometimes some of my Modbus Sensors are showing wrong values after restarting Home Assistant. The value is then way too high, for example I am reading temperature values or the current heating power of my house heating-system. Instead of showing the actual outside temperature it is showing a value of over 40°C or a heating power off 440 kW instead of 3 kW for example. Restarting Home Assistant is the only solution I found so far for resolving the problem. Some problematic Sensors in configuration are: "Aussentemperatur" or "Brennerleistung"
Modbus Device is a Solvis Heating System. Had no problems before 0.114