pymodbus loops indefinitely over received frame
nrodday opened this issue · 8 comments
Versions
- Python: 3.12.3
- OS: Debian 12 - 6.6.28+rpt-rpi-v8
- Pymodbus: 3.6.8
- Modbus Hardware (if used): RelayBoard R4M9B12, PH Sensor, Temp Sensor
Pymodbus Specific
- Server: rtu
- Client: rtu
Description
I am trying to use a relay board within HomeAssistant (HA). The modbus integration is using pymodbus underneath. For some strange reason a message cannot be parsed or digested within pymodbus. From there on, the modmos protocol does not work as expected anymore, command are significantly delayed or not sent at all, values from sensor cannot be read anymore, etc.
The log below shows the one frame that gets stuck and is looped over for forever.
What could be the cause?
Code and Logs
The code can be found here:
https://github.com/home-assistant/core/tree/dev/homeassistant/components/modbus
I did not modify anything from the integration.
code and logs here.
2024-07-25 18:41:42.044 DEBUG (MainThread) [pymodbus.logging] Adding transaction 12
2024-07-25 18:41:42.045 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer -
2024-07-25 18:41:42.045 DEBUG (MainThread) [pymodbus.logging] send: 0xc 0x4 0x0 0x0 0x0 0x1 0x30 0xd7
2024-07-25 18:41:42.073 DEBUG (MainThread) [pymodbus.logging] recv: 0xd 0xa 0x41 0x54 0x5f 0x45 0x52 0x52 0xd 0xa old_data: addr=None
2024-07-25 18:41:42.073 DEBUG (MainThread) [pymodbus.logging] Processing: 0xd 0xa 0x41 0x54 0x5f 0x45 0x52 0x52 0xd 0xa
2024-07-25 18:41:47.046 DEBUG (MainThread) [pymodbus.logging] Adding transaction 12
2024-07-25 18:41:47.047 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer - 0x52 0xd 0xa
2024-07-25 18:41:47.047 DEBUG (MainThread) [pymodbus.logging] send: 0xc 0x4 0x0 0x0 0x0 0x1 0x30 0xd7
2024-07-25 18:41:47.075 DEBUG (MainThread) [pymodbus.logging] recv: 0xd 0xa 0x41 0x54 0x5f 0x45 0x52 0x52 0xd 0xa old_data: addr=None
2024-07-25 18:41:47.076 DEBUG (MainThread) [pymodbus.logging] Processing: 0xd 0xa 0x41 0x54 0x5f 0x45 0x52 0x52 0xd 0xa
2024-07-25 18:41:52.048 DEBUG (MainThread) [pymodbus.logging] Adding transaction 12
2024-07-25 18:41:52.048 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer - 0x52 0xd 0xa
2024-07-25 18:41:52.049 DEBUG (MainThread) [pymodbus.logging] send: 0xc 0x4 0x0 0x0 0x0 0x1 0x30 0xd7
2024-07-25 18:41:52.077 DEBUG (MainThread) [pymodbus.logging] recv: 0xd 0xa 0x41 0x54 0x5f 0x45 0x52 0x52 0xd 0xa old_data: addr=None
2024-07-25 18:41:52.077 DEBUG (MainThread) [pymodbus.logging] Processing: 0xd 0xa 0x41 0x54 0x5f 0x45 0x52 0x52 0xd 0xa
I cannot talk about HA modbus, but pymodbus does not loop over the same message !
As the log clearly shows, it does a send, then a receive, and processings (which means send to app).
I am not sure where you see a loop.
Pymodbus only sends when the app request it, so it seems HA modbus request a send, maybe the loop is there.
The problem seems to be associated with HA as a single non-responsive sensor seems to be blocking all other modbus communication on the channel. That is why the relays are not working anymore when a sensor is disconnected. The HA modbus imllementation waits for the timeout, sends the message again, and so on - indefinitely.
Apart from that something is wrong, the send addresses slave OxC but the response is from oxD...that looks like a configuration mismatch.
Seems you are using an old pymodbus, we are at 3.6.9
I am now using pymodbus 3.6.9.
It was not pymodbus indefinitely looping over a frame but simply the outgoing frame being repeated due to non-responsiveness of the sensor.
What is strange though is that no other communication on the channel is possible during these retransmissions:
2024-07-26 11:19:45.759 DEBUG (MainThread) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-07-26 11:19:45.760 DEBUG (MainThread) [pymodbus.logging] Frame advanced, resetting header!!
2024-07-26 11:19:45.760 DEBUG (MainThread) [pymodbus.logging] Getting transaction 0
2024-07-26 11:19:45.791 DEBUG (MainThread) [pymodbus.logging] Adding transaction 0
2024-07-26 11:19:45.791 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer -
2024-07-26 11:19:45.792 DEBUG (MainThread) [pymodbus.logging] send: 0x1e 0x3 0x0 0x0 0x0 0x1 0x86 0x65
2024-07-26 11:19:45.893 DEBUG (MainThread) [pymodbus.logging] Adding transaction 0
2024-07-26 11:19:45.894 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer -
2024-07-26 11:19:45.894 DEBUG (MainThread) [pymodbus.logging] send: 0x1e 0x3 0x0 0x0 0x0 0x1 0x86 0x65
2024-07-26 11:19:45.996 DEBUG (MainThread) [pymodbus.logging] Adding transaction 0
2024-07-26 11:19:45.996 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer -
2024-07-26 11:19:45.996 DEBUG (MainThread) [pymodbus.logging] send: 0x1e 0x3 0x0 0x0 0x0 0x1 0x86 0x65
2024-07-26 11:19:46.098 DEBUG (MainThread) [pymodbus.logging] Adding transaction 0
2024-07-26 11:19:46.099 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer -
2024-07-26 11:19:46.099 DEBUG (MainThread) [pymodbus.logging] send: 0x1e 0x3 0x0 0x0 0x0 0x1 0x86 0x65
2024-07-26 11:19:46.200 DEBUG (MainThread) [pymodbus.logging] Connection lost comm due to Server not responding
2024-07-26 11:19:46.201 DEBUG (MainThread) [pymodbus.logging] callback_disconnected called: Server not responding
2024-07-26 11:19:46.202 ERROR (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: modbus_hub: Error: device: 30 address: 0 -> Modbus Error: [Input/Output] ERROR: No response received after 3 retries
2024-07-26 11:19:46.202 DEBUG (MainThread) [pymodbus.logging] Wait comm 100.0 ms before reconnecting.
2024-07-26 11:19:46.234 DEBUG (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: modbus_hub: Error: device: 30 address: 2 -> Modbus Error: [Connection] Not connected[AsyncModbusSerialClient /dev/ttyAMA5:0]
2024-07-26 11:19:46.265 DEBUG (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: modbus_hub: Error: device: 21 address: 0 -> Modbus Error: [Connection] Not connected[AsyncModbusSerialClient /dev/ttyAMA5:0]
2024-07-26 11:19:46.297 DEBUG (MainThread) [homeassistant.components.modbus.modbus] Pymodbus: modbus_hub: Error: device: 21 address: 1 -> Modbus Error: [Connection] Not connected[AsyncModbusSerialClient /dev/ttyAMA5:0]
2024-07-26 11:19:46.303 DEBUG (MainThread) [pymodbus.logging] Connecting to /dev/ttyAMA5.
2024-07-26 11:19:46.304 DEBUG (MainThread) [pymodbus.logging] Connecting comm
2024-07-26 11:19:46.306 DEBUG (MainThread) [pymodbus.logging] Connected to comm
2024-07-26 11:19:46.306 DEBUG (MainThread) [pymodbus.logging] Resetting frame - Current Frame in buffer -
I am unsure whether this problem is related to Home Assistant or the pymodbus library.
When one sensor is disconnected, pymodbus can also not reach the other sensor anymore. Once I reconnect the disconnected sensor, both sensors can be read just fine again. The same goes for other modbus entities, e.g. when a sensor is disconnected I cannot control the modbus relay anymore. Only during the printout of the "Not connected" lines and the reconnection of the serialport other modbus commands are processed, before freezing up again.
This is not a pymodbus problem, as you can see in the log and as I explained earlier.
No need to link HA issues here, we do not look at these issues, that is for the HA maintainers to do.
I already told you that you seem to have a faulty configuration, and with that I close the issue.
Good luck with your HA issue.