Pymodbus doesn't correctly handle Reassembled TCP segments

sthelen-enqs commented 8 months ago

Versions

Python: Python: 3.11.4
OS: Ubuntu 20.04
Pymodbus: pymodbus-3.7.0.dev0 (git commit 81df5b1cde349dddd32ac3c1fd97ec4b475c2512) 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

janiversen commented 8 months ago

We do check the length of the packet, but when a frame is split the each dap have it own length.

This seems to be bug in our transport layer, I will take a look later.

janiversen commented 8 months ago

Thanks for a very complete documentation, that helps a lot isolating the bug. I will use the data to create a specific test case, and then solve it.

janiversen commented 8 months ago

As a workaround while I work, you could consider trying the sync client, that is another implementation and might allow you to continue working.

sthelen-enqs commented 8 months ago

Thank you very much for the quick fix, I can confirm that the async client now works with this device on latest dev.

The sync client also worked in the interim yesterday, thanks for the suggestion.

pymodbus-dev / pymodbus