Pymodbus doesn't correctly handle Reassembled TCP segments #1922
Description
Versions
- Python: Python: 3.11.4
- OS: Ubuntu 20.04
- Pymodbus: pymodbus-3.7.0.dev0 (git commit 81df5b1) as well as 3.5.4
- Modbus Hardware (if used): SMA STP 6000TL-20 (version 02.51.02.R)
Pymodbus Specific
- Client: tcp - async
Description
When trying to read registers from the SMA STP 6000TL Inverter, the Modbus Response is split over 2 frames where the second frame only contains the last required byte. pymodbus doesn't seem to reassemble the modbus frames and instead tries parsing the first frame as a modbus response which it discards because it doesn't pass the Frame check. It then tries reading the second frame (consisting of only one byte) as a response and throws an exception because it can't decode it.
pymodbus should probably check the length of the tcp packet and only run the frame check once the complete packet has arrived. I've attached the client code, pymodbus logs and a wireshark capture of the modbus traffic.
Code and Logs
20240104_tcp_reassembly.pcapng.gz
import asyncio
import pymodbus
from pymodbus.client import AsyncModbusTcpClient
from pymodbus.constants import Endian
from pymodbus.exceptions import ModbusException
from pymodbus.payload import BinaryPayloadDecoder
from pymodbus.pdu import ExceptionResponse
pymodbus.pymodbus_apply_logging_config("DEBUG")
async def main():
async with AsyncModbusTcpClient(
host="127.0.0.1", port=5502, reconnect_delay=0
) as mbus:
response = await mbus.read_holding_registers(42109, 4, slave=1)
decoder = BinaryPayloadDecoder.fromRegisters(
response.registers, byteorder=Endian.BIG, wordorder=Endian.BIG
)
_serial = decoder.decode_32bit_uint()
_susy_id = decoder.decode_16bit_uint()
unit_id = decoder.decode_16bit_uint()
if __name__ == "__main__":
asyncio.run(main())Logs:
2024-01-04 11:16:16,385 DEBUG logging:103 Connecting to 127.0.0.1:5502.
2024-01-04 11:16:16,385 DEBUG logging:103 Connecting comm
2024-01-04 11:16:16,385 DEBUG logging:103 Connected to comm
2024-01-04 11:16:16,385 DEBUG logging:103 callback_connected called
2024-01-04 11:16:16,385 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0xa4 0x7d 0x0 0x4
2024-01-04 11:16:16,385 DEBUG logging:103 Adding transaction 1
2024-01-04 11:16:16,635 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x0 0xb5 0x12 0x2f 0x37 0x21 0x0 old_data: addr=None
2024-01-04 11:16:16,635 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x0 0xb5 0x12 0x2f 0x37 0x21 0x0
2024-01-04 11:16:16,635 DEBUG logging:103 Frame check failed, ignoring!!
2024-01-04 11:16:16,635 DEBUG logging:103 Resetting frame - Current Frame in buffer - 0x0 0x1 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x0 0xb5 0x12 0x2f 0x37 0x21 0x0
2024-01-04 11:16:16,719 DEBUG logging:103 recv: 0x3 old_data: addr=None
2024-01-04 11:16:16,719 DEBUG logging:103 Processing: 0x3
2024-01-04 11:16:16,719 DEBUG logging:103 Factory Response[ReadHoldingRegistersResponse': 3]
2024-01-04 11:16:16,719 ERROR logging:115 General exception: index out of range
2024-01-04 11:16:16,719 DEBUG logging:103 Resetting frame - Current Frame in buffer - 0x3
Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.tcp.AsyncModbusTcpClient object at 0x7fa70e325f70>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
File "/usr/lib/python3.8/asyncio/selector_events.py", line 862, in _read_ready__data_received
self._protocol.data_received(data)
File "/home/simon/tools/pymodbus/pymodbus/transport/transport.py", line 318, in data_received
self.datagram_received(data, None)
File "/home/simon/tools/pymodbus/pymodbus/transport/transport.py", line 352, in datagram_received
cut = self.callback_data(self.recv_buffer, addr=addr)
File "/home/simon/tools/pymodbus/pymodbus/client/base.py", line 186, in callback_data
self.framer.processIncomingPacket(data, self._handle_response, slave=0)
File "/home/simon/tools/pymodbus/pymodbus/framer/base.py", line 139, in processIncomingPacket
self.frameProcessIncomingPacket(single, callback, slave, **kwargs)
File "/home/simon/tools/pymodbus/pymodbus/framer/socket_framer.py", line 136, in frameProcessIncomingPacket
self._process(callback, tid, error=True)
File "/home/simon/tools/pymodbus/pymodbus/framer/socket_framer.py", line 154, in _process
raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2024-01-04 11:16:16,721 DEBUG logging:103 Connection lost comm due to Modbus Error: [Input/Output] Unable to decode request
2024-01-04 11:16:16,721 DEBUG logging:103 Getting transaction 1
Traceback (most recent call last):
File "bug_reproducer.py", line 27, in <module>
asyncio.run(main())
File "/usr/lib/python3.8/asyncio/runners.py", line 44, in run
return loop.run_until_complete(main)
File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
return future.result()
File "bug_reproducer.py", line 17, in main
response = await mbus.read_holding_registers(42109, 4, slave=1)
File "/home/simon/tools/pymodbus/pymodbus/client/base.py", line 167, in async_execute
resp = await asyncio.wait_for(
File "/usr/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
return fut.result()
pymodbus.exceptions.ConnectionException: Modbus Error: [Connection] Connection lost during request