RTU Framer discards packets splitted into two calls to "processIncomingPacket"

[RonnyDe1982]

Versions

• Python: 3.6.7
• OS: Ubuntu 18.10
• Pymodbus: 2.1.0 (rtu_framer.py function ProcessIncomingPacket patched to 2.2.0)
• Modbus Hardware (if used):

Pymodbus Specific

• Server: rtu - async

Description

The RTU Framer had a known issue related to modbus requests not served by the library but other physical modbus devices. This issues seems to be fixed in branch "pymodbus-2.2.0".

However, the suggested bugfix in pymodbus/rtu:framer.py, lines 231-233 introduces another problem for large modbus requests which cannot be passes in one single data frame to the function processIncomingPacket.

Whenever an incomplete packet has been received this packet is discarded since "checkFrame" returns false.

Known workaround:

if self.isFrameReady():
            if self.checkFrame():
                if self._validate_unit_id(unit, single):
                    self._process(callback)
                else:
                    _logger.debug("Not a valid unit id - {}, "
                                  "ignoring!!".format(self._header['uid']))
                    self.resetFrame()
            else:
                if len(self._buffer) > self._header["len"]:
                       _logger.debug("Frame check failed, ignoring!!")
                      self.resetFrame()
        else:
            _logger.debug("Frame - [{}] not ready".format(data))

[meierphil]

I stumbled upon the same issue:

Versions

Python: 3.6.4, 3.7.3
OS: Windows10

and
Python 3.6.5
OS: Ubuntu 18.04.1 LTS

with
Pymodbus: 2.2.0rc4
Hardware: Voegtlin red-y smart Series GSM mass flow meter

Description

When I integrated @RonnyDe1982's workaround, a key error was raised for self._header['len']:

Received
    self.framer.processIncomingPacket(data, self._handleResponse, unit=unit)
  File "C:\Users\username\venv\lib\site-packages\pymodbus\framer\rtu_framer.py", line 234, in processIncomingPacket
    if len(self._buffer) > self._header["len"]:
KeyError: 'len'

Hence, I adapted the snippet to:

if self.isFrameReady():
    if self.checkFrame():
        if self._validate_unit_id(unit, single):
            self._process(callback)
        else:
            _logger.debug("Not a valid unit id - {}, "
                          "ignoring!!".format(self._header['uid']))
            self.resetFrame()
    else:
        try:
            if self._header['len']:
                if len(self._buffer) > self._header['len']:
                    _logger.debug("Frame check failed, ignoring!!")
                    self.resetFrame()
        except KeyError:
            pass
else:
    _logger.debug("Frame - [{}] not ready".format(data))

Not the neatest solution, but it worked for my case. I guess it is worth to dig a little bit deeper to find the cause of this error.

[dhoomakethu]

@meierphil Thanks for the hints and workaround. I will try to get a solution for this

[Howlinmoon]

I'm trying to figure out if I am seeing this same split packet issue with the RTU framer.

My master device is sending this command:

[2019-09-13T12:09:37.412Z][DEBUG]-ModbusMaster.py:43,Sending request: address=1, function=3, data=[0, 0, 0, 1]

And the Pymodbus Sync server is reporting this error:

2019-09-13 07:51:33,892 MainThread DEBUG sync :45 Client Connected [/dev/ttyUSB1:/dev/ttyUSB1]
2019-09-13 07:51:33,892 MainThread DEBUG sync :522 Started thread to serve client
2019-09-13 07:51:51,159 MainThread DEBUG rtu_framer :232 Frame check failed, ignoring!!
2019-09-13 07:51:51,159 MainThread DEBUG rtu_framer :128 Resetting frame - Current Frame in buffer - 0x1 0x3 0x0 0x0 0x0
2019-09-13 07:51:51,165 MainThread DEBUG rtu_framer :232 Frame check failed, ignoring!!
2019-09-13 07:51:51,165 MainThread DEBUG rtu_framer :128 Resetting frame - Current Frame in buffer - 0x1 0x84 0xa

It looks to me like "0x1 0x3 0x0 0x0 0x0" is missing the final "0x1" which is in the second frame - along with "0x84 & 0xa"

Is this the same issue?

[maximeLeurent]

Hi,

I just face the same issue with a TCP device.
I am using a SMA Sunny Tripower device. In SMA FAQ, they are talking about message split https://www.sma.de/fr/produits/surveillance-controle/interface-protocole-modbus.html (section Modbus provides two answers upon request).

Here a piece of code, showing my issue. In sync mode there is no problem; In async mode, the message is split in two piece of code :
-0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x3 -> ignored
-0x71 -> generated a error; because no header

import logging
from pymodbus.client.sync import ModbusTcpClient as SyncModbusClient
from pymodbus.client.asynchronous.asyncio import AsyncioModbusTcpClient,ModbusClientProtocol
from pymodbus.framer.socket_framer import ModbusSocketFramer
from pymodbus.factory import ClientDecoder
from pymodbus.utilities import hexlify_packets
import asyncio
from pymodbus.client.asynchronous import schedulers
ip = "192.168.0.3"
port = 502
num_reg =30775
nb_reg = 2
unit = 3
FORMAT = ('%(asctime)-15s %(threadName)-15s '
          '%(levelname)-8s %(module)-15s:%(lineno)-8s %(message)s')
logging.basicConfig(format=FORMAT)
log = logging.getLogger()
log.setLevel(logging.DEBUG)


def run_sync_client():
    log.debug("")
    log.debug("-----------Sync client---------------------------")
    client = SyncModbusClient(ip, port=port)
    client.connect()
    rr = client.read_holding_registers(num_reg,nb_reg, unit=unit)
    print(rr)
    print(rr.registers)
    log.debug("--------------Sync client Finish---------------")
    log.debug("")

async def start_async_test(client):
    await client.connect()
    rr = await client.protocol.read_holding_registers(num_reg,nb_reg, unit=unit)
    print(rr)
    print(rr.registers)



def run_async_client():
    log.debug("-----------ASync client---------------------------")
    loop = asyncio.new_event_loop()
    assert not loop.is_running()
    asyncio.set_event_loop(loop)
    client = AsyncioModbusTcpClient( host= ip, port=port, loop=loop)#,protocol_class = MyModbusClientProtocol
    loop.run_until_complete(start_async_test(client))
    loop.close()
    log.debug("--------------ASync client Finish---------------")
    log.debug("")
run_sync_client()
run_async_client()

2019-12-16 15:34:29,878 MainThread      DEBUG    test_TCP_STP   :23       
2019-12-16 15:34:29,878 MainThread      DEBUG    test_TCP_STP   :24       -----------Sync client---------------------------
2019-12-16 15:34:29,881 MainThread      DEBUG    transaction    :115      Current transaction state - IDLE
2019-12-16 15:34:29,881 MainThread      DEBUG    transaction    :120      Running transaction 1
2019-12-16 15:34:29,881 MainThread      DEBUG    transaction    :219      SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x3 0x3 0x78 0x37 0x0 0x2
2019-12-16 15:34:29,881 MainThread      DEBUG    sync           :75       New Transaction state 'SENDING'
2019-12-16 15:34:29,881 MainThread      DEBUG    transaction    :228      Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2019-12-16 15:34:30,061 MainThread      DEBUG    transaction    :304      Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2019-12-16 15:34:30,061 MainThread      DEBUG    transaction    :233      RECV: 0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x6 0x7d
2019-12-16 15:34:30,061 MainThread      DEBUG    socket_framer  :147      Processing: 0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x6 0x7d
2019-12-16 15:34:30,061 MainThread      DEBUG    factory        :266      Factory Response[ReadHoldingRegistersResponse: 3]
2019-12-16 15:34:30,062 MainThread      DEBUG    transaction    :383      Adding transaction 1
2019-12-16 15:34:30,062 MainThread      DEBUG    transaction    :394      Getting transaction 1
2019-12-16 15:34:30,062 MainThread      DEBUG    transaction    :193      Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
ReadRegisterResponse (2)
[0, 1661]
2019-12-16 15:34:30,062 MainThread      DEBUG    test_TCP_STP   :30       --------------Sync client Finish---------------
2019-12-16 15:34:30,062 MainThread      DEBUG    test_TCP_STP   :31       
2019-12-16 15:34:30,062 MainThread      DEBUG    test_TCP_STP   :47       -----------ASync client---------------------------
2019-12-16 15:34:30,062 MainThread      DEBUG    selector_events:53       Using selector: EpollSelector
2019-12-16 15:34:30,063 MainThread      DEBUG    __init__       :386      Connecting.
2019-12-16 15:34:30,064 MainThread      DEBUG    __init__       :95       Client connected to modbus server
2019-12-16 15:34:30,064 MainThread      INFO     __init__       :400      Protocol made connection.
2019-12-16 15:34:30,064 MainThread      INFO     __init__       :391      Connected to 192.168.0.3:502.
2019-12-16 15:34:30,064 MainThread      DEBUG    __init__       :129      send: 0x0 0x1 0x0 0x0 0x0 0x6 0x3 0x3 0x78 0x37 0x0 0x2
2019-12-16 15:34:30,064 MainThread      DEBUG    transaction    :383      Adding transaction 1
2019-12-16 15:34:30,336 MainThread      DEBUG    __init__       :138      recv: 0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x6
2019-12-16 15:34:30,336 MainThread      DEBUG    socket_framer  :147      Processing: 0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x6
2019-12-16 15:34:30,336 MainThread      DEBUG    socket_framer  :159      Frame check failed, ignoring!!
2019-12-16 15:34:30,337 MainThread      DEBUG    __init__       :138      recv: 0x7d
2019-12-16 15:34:30,338 MainThread      DEBUG    socket_framer  :147      Processing: 0x7d
2019-12-16 15:34:30,338 MainThread      DEBUG    factory        :266      Factory Response[125]
2019-12-16 15:34:30,338 MainThread      ERROR    factory        :245      Unable to decode response Modbus Error: Unknown response 125
2019-12-16 15:34:30,338 MainThread      ERROR    base_events    :1604     Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.asynchronous.asyncio.ModbusClientProtocol object at 0x7f3ea4d05d90>
transport: <_SelectorSocketTransport fd=7 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.7/asyncio/selector_events.py", line 816, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/home/ems/.local/lib/python3.7/site-packages/pymodbus/client/asynchronous/asyncio/__init__.py", line 193, in data_received
    self._dataReceived(data)
  File "/home/ems/.local/lib/python3.7/site-packages/pymodbus/client/asynchronous/asyncio/__init__.py", line 140, in _dataReceived
    self.framer.processIncomingPacket(data, self._handleResponse, unit=unit)
  File "/home/ems/.local/lib/python3.7/site-packages/pymodbus/framer/socket_framer.py", line 165, in processIncomingPacket
    self._process(callback, error=True)
  File "/home/ems/.local/lib/python3.7/site-packages/pymodbus/framer/socket_framer.py", line 175, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2019-12-16 15:34:30,340 MainThread      DEBUG    __init__       :105      Client disconnected from modbus server: Modbus Error: [Input/Output] Unable to decode request
2019-12-16 15:34:30,340 MainThread      DEBUG    transaction    :394      Getting transaction 1
2019-12-16 15:34:30,340 MainThread      INFO     __init__       :413      Protocol lost connection.

I managed to deal my problem with rewriting processIncomingPacket of the Framer.
I don't understand the goal of the while loop in this function, I removed it because the buffer is not reset at each call of processIncomingPacket.
This piece of code is not safe, because if the end of the message is lost, the message will not be process. May be a timeout can be added.

class MyFramer(ModbusSocketFramer):
    def processIncomingPacket(self, data, callback, unit, **kwargs):
        if not isinstance(unit, (list, tuple)):
            unit = [unit]
        single = kwargs.get("single", False)
        logging.debug("Processing: " + hexlify_packets(data))
        self.addToFrame(data)

        #while True:
        if self.isFrameReady():
            if self.checkFrame():
                if self._validate_unit_id(unit, single):
                    self._process(callback)
                else:
                    logging.debug("Not a valid unit id - {}, "
                                  "ignoring!!".format(self._header['uid']))
                    self.resetFrame()
            else:
                logging.debug("Frame check failed, wait end of message")
                #self.resetFrame()
        else:
            if len(self._buffer):
                # Possible error ???
                if self._header['len'] < 2:
                    self._process(callback, error=True)
            #break

class MyModbusClientProtocol(ModbusClientProtocol):
    def __init__(self, *args, **kargs):
         kargs["framer"] = MyFramer(ClientDecoder())
         super().__init__(self,  *args, **kargs)

The corresponding logs are : (the reply message has changed due to the state of my device)

2019-12-16 16:03:42,014 MainThread      DEBUG    test_TCP_STP   :41       -----------ASync client---------------------------
2019-12-16 16:03:42,014 MainThread      DEBUG    selector_events:53       Using selector: EpollSelector
2019-12-16 16:03:42,015 MainThread      DEBUG    __init__       :386      Connecting.
2019-12-16 16:03:42,016 MainThread      DEBUG    __init__       :95       Client connected to modbus server
2019-12-16 16:03:42,016 MainThread      INFO     __init__       :400      Protocol made connection.
2019-12-16 16:03:42,016 MainThread      INFO     __init__       :391      Connected to 192.168.0.3:502.
2019-12-16 16:03:42,017 MainThread      DEBUG    __init__       :129      send: 0x0 0x1 0x0 0x0 0x0 0x6 0x3 0x3 0x78 0x37 0x0 0x2
2019-12-16 16:03:42,017 MainThread      DEBUG    transaction    :383      Adding transaction 1
2019-12-16 16:03:42,163 MainThread      DEBUG    __init__       :138      recv: 0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x3
2019-12-16 16:03:42,163 MainThread      DEBUG    test_TCP_STP   :61       Processing: 0x0 0x1 0x0 0x0 0x0 0x7 0x3 0x3 0x4 0x0 0x0 0x3
2019-12-16 16:03:42,163 MainThread      DEBUG    test_TCP_STP   :74       Frame check failed, wait end of message
2019-12-16 16:03:42,164 MainThread      DEBUG    __init__       :138      recv: 0x41
2019-12-16 16:03:42,164 MainThread      DEBUG    test_TCP_STP   :61       Processing: 0x41
2019-12-16 16:03:42,164 MainThread      DEBUG    factory        :266      Factory Response[ReadHoldingRegistersResponse: 3]
2019-12-16 16:03:42,164 MainThread      DEBUG    transaction    :394      Getting transaction 1
ReadRegisterResponse (2)
[0, 833]
2019-12-16 16:03:42,164 MainThread      DEBUG    test_TCP_STP   :48       --------------ASync client Finish---------------
2019-12-16 16:03:42,164 MainThread      DEBUG    test_TCP_STP   :49       

[nduongn]

I'm trying to figure out if I am seeing this same split packet issue with the RTU framer.

My master device is sending this command:

[2019-09-13T12:09:37.412Z][DEBUG]-ModbusMaster.py:43,Sending request: address=1, function=3, data=[0, 0, 0, 1]

And the Pymodbus Sync server is reporting this error:

2019-09-13 07:51:33,892 MainThread DEBUG sync :45 Client Connected [/dev/ttyUSB1:/dev/ttyUSB1]
2019-09-13 07:51:33,892 MainThread DEBUG sync :522 Started thread to serve client
2019-09-13 07:51:51,159 MainThread DEBUG rtu_framer :232 Frame check failed, ignoring!!
2019-09-13 07:51:51,159 MainThread DEBUG rtu_framer :128 Resetting frame - Current Frame in buffer - 0x1 0x3 0x0 0x0 0x0
2019-09-13 07:51:51,165 MainThread DEBUG rtu_framer :232 Frame check failed, ignoring!!
2019-09-13 07:51:51,165 MainThread DEBUG rtu_framer :128 Resetting frame - Current Frame in buffer - 0x1 0x84 0xa

It looks to me like "0x1 0x3 0x0 0x0 0x0" is missing the final "0x1" which is in the second frame - along with "0x84 & 0xa"

Is this the same issue?

I met the same issue like yours.

[nduongn]

I'm trying to figure out if I am seeing this same split packet issue with the RTU framer.

My master device is sending this command:

[2019-09-13T12:09:37.412Z][DEBUG]-ModbusMaster.py:43,Sending request: address=1, function=3, data=[0, 0, 0, 1]

And the Pymodbus Sync server is reporting this error:

2019-09-13 07:51:33,892 MainThread DEBUG sync :45 Client Connected [/dev/ttyUSB1:/dev/ttyUSB1]
2019-09-13 07:51:33,892 MainThread DEBUG sync :522 Started thread to serve client
2019-09-13 07:51:51,159 MainThread DEBUG rtu_framer :232 Frame check failed, ignoring!!
2019-09-13 07:51:51,159 MainThread DEBUG rtu_framer :128 Resetting frame - Current Frame in buffer - 0x1 0x3 0x0 0x0 0x0
2019-09-13 07:51:51,165 MainThread DEBUG rtu_framer :232 Frame check failed, ignoring!!
2019-09-13 07:51:51,165 MainThread DEBUG rtu_framer :128 Resetting frame - Current Frame in buffer - 0x1 0x84 0xa

It looks to me like "0x1 0x3 0x0 0x0 0x0" is missing the final "0x1" which is in the second frame - along with "0x84 & 0xa"

Is this the same issue?

Hi, you can use https://github.com/riptideio/pymodbus/pull/466 to fix your issue. I use this and it works.