search

pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.29k stars 936 forks source link

AsyncModbusTcpClient never recovers after bad response #1545

Closed JonasNorling closed 1 year ago

JonasNorling commented 1 year ago

I have a modbus server that occasionally returns an invalid response to read-holding-registers, where the "number of bytes" number in the PDU is higher than the actual number of bytes in the response. AsyncModbusTcpClient reacts by disconnecting — which is fine — but after automatically reconnecting it is unable to handle further responses.

From what I can see: ReadRegistersResponseBase.decode() crashes in struct.unpack due to lack of data, because the length indication in the packet was incorrect. This exception isn't caught anywhere and the connection is closed. Upon reconnection, the ModbusSocketFramer is not reset, so when the next response comes in we try to parse the old broken response again. This repeats forever, the framer buffer getting larger every time.

Python: 3.10.9 (also tested 3.9.16) OS: Linux Pymodbus: 3.2.2 (also tested dev2.x-543-gd347bc8)

Code and Logs

Reproducer client

#!/usr/bin/env python
import asyncio
import logging

import pymodbus
from pymodbus.client import AsyncModbusTcpClient

pymodbus.pymodbus_apply_logging_config()
log = logging.getLogger()

async def main():
    client = AsyncModbusTcpClient('localhost', port=5020)
    await client.connect()

    for i in range(7):
        log.info(f'{i}: Sending request on client {client}')
        try:
            result = await client.read_holding_registers(3000, 1)
            log.info(f'{i}: {result}')
        except Exception as e:
            log.error(f'{i}: {e}')
        while not client.connected:
            await asyncio.sleep(0.1)

asyncio.run(main())

Reproducer server

#!/usr/bin/env python
import socketserver
import struct
import logging

log = logging.getLogger()

class Handler(socketserver.StreamRequestHandler):
    def handle(self):
        log.info('New connection')
        while True:
            data = self.request.recv(1024)
            if not data:
                break
            tid, pid, length, unit, fc = struct.unpack_from('>HHHBB', data)
            pdu = data[8:8+length]
            log.debug(f'Got {(tid, pid, length, unit, fc)}, PDU {pdu}')
            if fc == 3 or fc == 4:
                address, count = struct.unpack('>HH', pdu)
                header_len = count * 2 + 3
                registers_len = count * 2
                if tid == 4:
                    log.info('Sending wrong length')
                    registers_len += 8
                response = struct.pack('>HHHBB', tid, pid, header_len, unit, fc)
                response += struct.pack('>B', registers_len)
                response += struct.pack('>H', tid) * count
                self.request.send(response)
            else:
                break
        self.request.close()

class Server(socketserver.ThreadingMixIn, socketserver.TCPServer):
    daemon_threads = True
    allow_reuse_address = True

if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG)
    server = Server(('0.0.0.0', 5020), Handler)
    server.serve_forever()

Log

$ tests/modbus_reproducer.py 
2023-05-24 09:17:48,458 DEBUG logging:102 Connecting to localhost:5020.
2023-05-24 09:17:48,458 DEBUG logging:102 Connecting.
2023-05-24 09:17:48,463 DEBUG logging:102 Connected comm
2023-05-24 09:17:48,463 INFO  logging:96 Connected to localhost:5020.
2023-05-24 09:17:48,464 DEBUG logging:102 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:48,464 DEBUG logging:102 Adding transaction 1
2023-05-24 09:17:48,464 DEBUG logging:102 recv: 0x0 0x1 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x1
2023-05-24 09:17:48,464 DEBUG logging:102 Processing: 0x0 0x1 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x1
2023-05-24 09:17:48,464 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:48,464 DEBUG logging:102 Getting transaction 1
2023-05-24 09:17:48,464 DEBUG logging:102 send: 0x0 0x2 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:48,464 DEBUG logging:102 Adding transaction 2
2023-05-24 09:17:48,465 DEBUG logging:102 recv: 0x0 0x2 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x2
2023-05-24 09:17:48,465 DEBUG logging:102 Processing: 0x0 0x2 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x2
2023-05-24 09:17:48,465 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:48,465 DEBUG logging:102 Getting transaction 2
2023-05-24 09:17:48,465 DEBUG logging:102 send: 0x0 0x3 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:48,465 DEBUG logging:102 Adding transaction 3
2023-05-24 09:17:48,465 DEBUG logging:102 recv: 0x0 0x3 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x3
2023-05-24 09:17:48,465 DEBUG logging:102 Processing: 0x0 0x3 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x3
2023-05-24 09:17:48,465 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:48,465 DEBUG logging:102 Getting transaction 3
2023-05-24 09:17:48,466 DEBUG logging:102 send: 0x0 0x4 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:48,466 DEBUG logging:102 Adding transaction 4
2023-05-24 09:17:48,466 DEBUG logging:102 recv: 0x0 0x4 0x0 0x0 0x0 0x5 0x0 0x3 0xa 0x0 0x4
2023-05-24 09:17:48,466 DEBUG logging:102 Processing: 0x0 0x4 0x0 0x0 0x0 0x5 0x0 0x3 0xa 0x0 0x4
2023-05-24 09:17:48,466 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:48,466 ERROR logging:114 General exception: unpack requires a buffer of 2 bytes
Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.tcp.AsyncModbusTcpClient object at 0x7fcec3da44c0>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib64/python3.9/asyncio/selector_events.py", line 868, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/home/jonasn/src/pymodbus/pymodbus/client/base.py", line 207, in data_received
    self.framer.processIncomingPacket(data, self._handle_response, slave=0)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 173, in processIncomingPacket
    self._process(callback, tid)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 179, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:48,467 DEBUG logging:102 Connection lost comm due to Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:48,467 DEBUG logging:102 Getting transaction 4
2023-05-24 09:17:48,467 DEBUG logging:102 Waiting 100 ms reconnecting.
3: Modbus Error: [Connection] Connection lost during request
2023-05-24 09:17:48,568 DEBUG logging:102 Connecting to localhost:5020.
2023-05-24 09:17:48,568 DEBUG logging:102 Connecting.
2023-05-24 09:17:48,569 DEBUG logging:102 Connected comm
2023-05-24 09:17:48,569 INFO  logging:96 Connected to localhost:5020.
2023-05-24 09:17:48,669 DEBUG logging:102 send: 0x0 0x5 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:48,670 DEBUG logging:102 Adding transaction 5
2023-05-24 09:17:48,670 DEBUG logging:102 recv: 0x0 0x5 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x5
2023-05-24 09:17:48,670 DEBUG logging:102 Processing: 0x0 0x5 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x5
2023-05-24 09:17:48,670 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:48,670 ERROR logging:114 General exception: unpack requires a buffer of 2 bytes
Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.tcp.AsyncModbusTcpClient object at 0x7fcec3da44c0>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib64/python3.9/asyncio/selector_events.py", line 868, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/home/jonasn/src/pymodbus/pymodbus/client/base.py", line 207, in data_received
    self.framer.processIncomingPacket(data, self._handle_response, slave=0)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 173, in processIncomingPacket
    self._process(callback, tid)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 179, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:48,670 DEBUG logging:102 Connection lost comm due to Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:48,670 DEBUG logging:102 Getting transaction 5
2023-05-24 09:17:48,670 DEBUG logging:102 Waiting 100 ms reconnecting.
4: Modbus Error: [Connection] Connection lost during request
2023-05-24 09:17:48,771 DEBUG logging:102 Connecting to localhost:5020.
2023-05-24 09:17:48,771 DEBUG logging:102 Connecting.
2023-05-24 09:17:48,772 DEBUG logging:102 Connected comm
2023-05-24 09:17:48,772 INFO  logging:96 Connected to localhost:5020.
2023-05-24 09:17:48,871 DEBUG logging:102 send: 0x0 0x6 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:48,872 DEBUG logging:102 Adding transaction 6
2023-05-24 09:17:48,872 DEBUG logging:102 recv: 0x0 0x6 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x6
2023-05-24 09:17:48,872 DEBUG logging:102 Processing: 0x0 0x6 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x6
2023-05-24 09:17:48,872 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:48,872 ERROR logging:114 General exception: unpack requires a buffer of 2 bytes
Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.tcp.AsyncModbusTcpClient object at 0x7fcec3da44c0>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib64/python3.9/asyncio/selector_events.py", line 868, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/home/jonasn/src/pymodbus/pymodbus/client/base.py", line 207, in data_received
    self.framer.processIncomingPacket(data, self._handle_response, slave=0)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 173, in processIncomingPacket
    self._process(callback, tid)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 179, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:48,872 DEBUG logging:102 Connection lost comm due to Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:48,872 DEBUG logging:102 Getting transaction 6
2023-05-24 09:17:48,872 DEBUG logging:102 Waiting 100 ms reconnecting.
5: Modbus Error: [Connection] Connection lost during request
2023-05-24 09:17:48,973 DEBUG logging:102 Connecting to localhost:5020.
2023-05-24 09:17:48,973 DEBUG logging:102 Connecting.
2023-05-24 09:17:48,976 DEBUG logging:102 Connected comm
2023-05-24 09:17:48,976 INFO  logging:96 Connected to localhost:5020.
2023-05-24 09:17:49,075 DEBUG logging:102 send: 0x0 0x7 0x0 0x0 0x0 0x6 0x0 0x3 0xb 0xb8 0x0 0x1
2023-05-24 09:17:49,075 DEBUG logging:102 Adding transaction 7
2023-05-24 09:17:49,076 DEBUG logging:102 recv: 0x0 0x7 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x7
2023-05-24 09:17:49,076 DEBUG logging:102 Processing: 0x0 0x7 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x7
2023-05-24 09:17:49,076 DEBUG logging:102 Factory Response[ReadHoldingRegistersResponse': 3]
2023-05-24 09:17:49,076 ERROR logging:114 General exception: unpack requires a buffer of 2 bytes
Fatal error: protocol.data_received() call failed.
protocol: <pymodbus.client.tcp.AsyncModbusTcpClient object at 0x7fcec3da44c0>
transport: <_SelectorSocketTransport fd=6 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib64/python3.9/asyncio/selector_events.py", line 868, in _read_ready__data_received
    self._protocol.data_received(data)
  File "/home/jonasn/src/pymodbus/pymodbus/client/base.py", line 207, in data_received
    self.framer.processIncomingPacket(data, self._handle_response, slave=0)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 173, in processIncomingPacket
    self._process(callback, tid)
  File "/home/jonasn/src/pymodbus/pymodbus/framer/socket_framer.py", line 179, in _process
    raise ModbusIOException("Unable to decode request")
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:49,077 DEBUG logging:102 Connection lost comm due to Modbus Error: [Input/Output] Unable to decode request
2023-05-24 09:17:49,077 DEBUG logging:102 Getting transaction 7
2023-05-24 09:17:49,077 DEBUG logging:102 Waiting 100 ms reconnecting.
6: Modbus Error: [Connection] Connection lost during request
2023-05-24 09:17:49,178 DEBUG logging:102 Connecting to localhost:5020.
2023-05-24 09:17:49,178 DEBUG logging:102 Connecting.
2023-05-24 09:17:49,179 DEBUG logging:102 Connected comm
2023-05-24 09:17:49,179 INFO  logging:96 Connected to localhost:5020.
janiversen commented 1 year ago

If it only sends extra bytes from time to time, the automatic reconnect clears the buffer (in both client and server) so that works until next time the client receives trash bytes.

Try to test with dev, because we added code recently (not released) to solve a similar problem (server on multi drop line), and I expect it to solve your problem as well. It will be released early next month as version 3.3

janiversen commented 1 year ago

I will try to make a test case with your example and see if I can statically reproduce it and if so solve it.

janiversen commented 1 year ago

The buffer does not get bigger and bigger: This causes the exception (which is a real bug): ´´´ 2023-05-24 09:17:48,466 DEBUG logging:102 recv: 0x0 0x4 0x0 0x0 0x0 0x5 0x0 0x3 0xa 0x0 0x4 2023-05-24 09:17:48,466 DEBUG logging:102 Processing: 0x0 0x4 0x0 0x0 0x0 0x5 0x0 0x3 0xa 0x0 0x4 ´´´ After reconnect, a request is sent and the response is: ´´´ 2023-05-24 09:17:48,872 DEBUG logging:102 recv: 0x0 0x6 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x6 2023-05-24 09:17:48,872 DEBUG logging:102 Processing: 0x0 0x6 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x6 ´´´ As you can see "Processing" have nothing in common. The problem is that your device sends a faulty response again after the reconnect.

Let me see what I can do to cure the faulty response.

JonasNorling commented 1 year ago

Thanks! PR #1547 fixes the problem, by clearing the framer buffer on decode error. I gave the dev branch a quick try on my device as well, and it looks fine.