Modbus RTU client never recovers if bad serial line. Filling buffer.

Jendem commented 5 years ago

Versions

Python: 2.7
OS: Gentoo Linux
Pymodbus: 1.5.2 and 2.1.0
Modbus Hardware (if used): PLC using Modbus RTU over RS-485

Pymodbus Specific

Server: rtu - async

Description

What were you trying:

Modbus client on PLC is writing to pymodbus server using code 16 (Write Multiple Registers). If the serial line is disconnected and then connected again, the RTU framer never passes its checkFrame(self) method.

Code and Logs

Adding some logging to the file rtu_framer.py:

def checkFrame(self):
    """
    Check if the next frame is available.
    Return True if we were successful.

    1. Populate header
    2. Discard frame if UID does not match
    """
    try:
        self.populateHeader()
        _logger.debug("self._header: %s" % self._header)

        frame_size = self._header['len']
        _logger.debug("frame_size: %s" % frame_size)
        _logger.debug("buffer_size: %s" % len(self._buffer))
        data = self._buffer[:frame_size - 2]
        _logger.debug("data: %s" % hexlify_packets(data))

        crc = self._buffer[frame_size - 2:frame_size]
        _logger.debug("crc: %s" % hexlify_packets(crc))

        crc_val = (byte2int(crc[0]) << 8) + byte2int(crc[1])
        _logger.debug("crc_val: %s" % crc_val)
        return checkCRC(data, crc_val)
    # except (IndexError, KeyError):
    except Exception as ex:
        return False

What did you expect? A normal log is like this: The buffer grows until the package is complete, in this case to 33 elements.

factory:Factory Request[16]
framer.rtu_framer:Frame advanced, resetting header!!
framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
framer.rtu_framer:frame_size: 33
framer.rtu_framer:buffer_size: 8
framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0xc4
framer.rtu_framer:crc: 
framer.rtu_framer:RTU checkFrame: FALSE

server.async:Data Received: 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4
framer.rtu_framer:RTU isFrameReady:TRUE
framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
framer.rtu_framer:frame_size: 33
framer.rtu_framer:buffer_size: 16
framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4
framer.rtu_framer:crc: 
framer.rtu_framer:RTU checkFrame: FALSE

server.async:Data Received: 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4
framer.rtu_framer:RTU isFrameReady:TRUE
framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
framer.rtu_framer:frame_size: 33
framer.rtu_framer:buffer_size: 24
framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4
framer.rtu_framer:crc: 
framer.rtu_framer:RTU checkFrame: FALSE

server.async:Data Received: 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0x41
framer.rtu_framer:RTU isFrameReady:TRUE
framer.rtu_framer:self._header: {'crc': 'A', 'uid': 5, 'len': 33}
framer.rtu_framer:frame_size: 33
framer.rtu_framer:buffer_size: 32
framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc
framer.rtu_framer:crc: 0x41
framer.rtu_framer:RTU checkFrame: FALSE

server.async:Data Received: 0x35
framer.rtu_framer:RTU isFrameReady:TRUE
framer.rtu_framer:self._header: {'crc': 'A5', 'uid': 5, 'len': 33}
framer.rtu_framer:frame_size: 33
framer.rtu_framer:buffer_size: 33
framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc
framer.rtu_framer:crc: 0x41 0x35
framer.rtu_framer:crc_val: 16693
framer.rtu_framer:RTU checkFrame:TRUE
framer.rtu_framer:Getting Frame - 0x10 0x0 0xc8 0x0 0xc 0x18 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc 0xc4 0xc

What has happened, what went wrong If the communication is broken, the buffer grows, because the CRC vil never match. Notice the last two bytes 0x18 0x3a are wrong in the first pymodbus.server.async:Data Received log.

pymodbus.factory:Factory Request[16]
pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
pymodbus.datastore.context:validate[16] 200:12
pymodbus.datastore.context:setValues[16] 200:12
pymodbus.server.async:send: 051000c8000c4076
modbus-slave:Data received.
pymodbus.server.async:Data Received: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 8
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a
pymodbus.framer.rtu_framer:crc: 
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

pymodbus.server.async:Data Received: 0x18 0x3a 0x98 0xff
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 12
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a 0x18 0x3a 0x98 0xff
pymodbus.framer.rtu_framer:crc: 
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

pymodbus.server.async:Data Received: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x50
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 20
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a 0x18 0x3a 0x98 0xff 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x50
pymodbus.framer.rtu_framer:crc: 
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

pymodbus.server.async:Data Received: 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': '', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 28
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a 0x18 0x3a 0x98 0xff 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50
pymodbus.framer.rtu_framer:crc: 
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

pymodbus.server.async:Data Received: 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': 'P8', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 36
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a 0x18 0x3a 0x98 0xff 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38
pymodbus.framer.rtu_framer:crc: 0x50 0x38
pymodbus.framer.rtu_framer:crc_val: 20536
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

pymodbus.server.async:Data Received: 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x53
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': 'P8', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 44
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a 0x18 0x3a 0x98 0xff 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38
pymodbus.framer.rtu_framer:crc: 0x50 0x38
pymodbus.framer.rtu_framer:crc_val: 20536
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

pymodbus.server.async:Data Received: 0x99
pymodbus.framer.rtu_framer:RTU isFrameReady:TRUE
pymodbus.framer.rtu_framer:self._header: {'crc': 'P8', 'uid': 5, 'len': 33}
pymodbus.framer.rtu_framer:frame_size: 33
pymodbus.framer.rtu_framer:buffer_size: 45
pymodbus.framer.rtu_framer:data: 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x3a 0x18 0x3a 0x98 0xff 0x5 0x10 0x0 0xc8 0x0 0xc 0x18 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38 0x50 0x38
pymodbus.framer.rtu_framer:crc: 0x50 0x38
pymodbus.framer.rtu_framer:crc_val: 20536
pymodbus.framer.rtu_framer:RTU checkFrame: FALSE

What did you expect? Some kind of reset if the buffer grows larger than the expected size.

dhoomakethu commented 5 years ago

Have you checked the latest pymodbus 2.1.0 ? There was a similar issue reported and was fixed

Jendem commented 5 years ago

I have now tried with the latest version, 2.1.0, but the problem still exists. The if checkFrame() is never true in processIncomingPacket(...) in rtu_framer.py.

Maybe it could compare frame_size and len(self._buffer), and if the buffer grows beyond the frame size, it should call self.resetFrame()?

dhoomakethu commented 5 years ago

Ok, Thanks for the confirmation. I will take a look.

pazzarpj commented 5 years ago

Can confirm am having the same issue

pazzarpj commented 5 years ago

Added a potential fix and test results in comments #363 .

janiversen commented 2 years ago

solved on current dev.

Feel free to open a new PR, if you still experience problems.

pymodbus-dev / pymodbus