pymodbus-dev
RTU Framer discards packets splitted into two calls to "processIncomingPacket"
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))
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.
@meierphil Thanks for the hints and workaround. I will try to get a solution for this
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,
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
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.
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.