Serial request that worked for older versions stopped working in v3.7.4

[MatthiasJaeger]

I'm using pymodbus to debug a hardware product that provides a MODBUS server functionality. I encountered some functionality that works when I use older pymodbus versions (I tested v3.7.1, v3.7.2 and v3.7.3) but not in the most recent (v3.7.4).

Any help with identifying if this is an issue with the hardware that now comes to light due to changed pymodbus behavior or a bug in pymodbus would be very welcome.

This is a minimal example that produces the issue (with my hardware):

import pymodbus
from pymodbus.client import ModbusSerialClient

pymodbus.pymodbus_apply_logging_config("DEBUG")

port = '/dev/ttyUSB0'  # Replace with your serial port
baudrate = 115200  # Changed baud rate to 115200


# connect to client
client = ModbusSerialClient(port=port, baudrate=baudrate)
connection = client.connect()

# send example request
result = client.read_device_information(slave=2, read_code=1, object_id=0)

With pymodbus v3.7.3 I get:

2024-11-05 21:18:20,770 DEBUG transaction:182 Current transaction state - IDLE
2024-11-05 21:18:20,770 DEBUG transaction:188 Running transaction 1
2024-11-05 21:18:20,770 DEBUG transaction:296 SEND: 0x2 0x2b 0xe 0x1 0x0 0x34 0x77
2024-11-05 21:18:20,770 DEBUG base:247 New Transaction state "SENDING"
2024-11-05 21:18:20,770 DEBUG transaction:320 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-11-05 21:18:20,781 DEBUG transaction:412 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-11-05 21:18:20,781 DEBUG transaction:327 RECV: 0x2 0x2b 0xe 0x1 0x3 0x0 0x0 0x3 0x0 0xa 0x4f 0x70 0x74 0x65 0x63 0x74 0x20 0x4c 0x74 0x64 0x1 0x4 0x4c 0x52 0x31 0x36 0x2 0x18 0x76 0x30 0x2e 0x39 0x2e 0x37 0x34 0x2d 0x39 0x2d 0x67 0x32 0x62 0x31 0x62 0x65 0x30 0x38 0x2d 0x64 0x69 0x72 0x74 0x79 0x2e 0x8a
2024-11-05 21:18:20,781 DEBUG base:101 Processing: 0x2 0x2b 0xe 0x1 0x3 0x0 0x0 0x3 0x0 0xa 0x4f 0x70 0x74 0x65 0x63 0x74 0x20 0x4c 0x74 0x64 0x1 0x4 0x4c 0x52 0x31 0x36 0x2 0x18 0x76 0x30 0x2e 0x39 0x2e 0x37 0x34 0x2d 0x39 0x2d 0x67 0x32 0x62 0x31 0x62 0x65 0x30 0x38 0x2d 0x64 0x69 0x72 0x74 0x79 0x2e 0x8a
2024-11-05 21:18:20,781 DEBUG factory:259 Factory Response[ReadDeviceInformationResponse': 43]
2024-11-05 21:18:20,781 DEBUG base:119 Frame advanced, resetting header!!
2024-11-05 21:18:20,781 DEBUG transaction:66 Adding transaction 0
2024-11-05 21:18:20,781 DEBUG transaction:77 Getting transaction 1
2024-11-05 21:18:20,781 DEBUG transaction:77 Getting transaction 0
2024-11-05 21:18:20,782 DEBUG transaction:253 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"

With pymodbus v3.7.7 I get:

2024-11-05 21:30:20,521 DEBUG transaction:184 Current transaction state - IDLE
2024-11-05 21:30:20,521 DEBUG transaction:193 Running transaction 0
2024-11-05 21:30:20,521 DEBUG transaction:293 SEND: 0x2 0x2b 0xe 0x1 0x0 0x34 0x77
2024-11-05 21:30:20,521 DEBUG base:250 New Transaction state "SENDING"
2024-11-05 21:30:20,521 DEBUG transaction:317 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-11-05 21:30:20,535 DEBUG transaction:419 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-11-05 21:30:20,535 DEBUG transaction:324 RECV: 0x2 0x2b 0xe 0x1
2024-11-05 21:30:20,535 DEBUG base:92 Processing: 0x2 0x2b 0xe 0x1
Traceback (most recent call last):
  File "(...)/modbus_testcase_reporting.py", line 15, in <module>
    result = client.read_device_information(slave=2, read_code=1, object_id=0)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/client/mixin.py", line 459, in read_device_information
    return self.execute(no_response_expected, pdu_mei.ReadDeviceInformationRequest(read_code, object_id, slave=slave))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/client/base.py", line 239, in execute
    return self.transaction.execute(no_response_expected, request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/transaction.py", line 241, in execute
    used_len, pdu = self.client.framer.processIncomingFrame(self.databuffer)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/framer/base.py", line 77, in processIncomingFrame
    data_len, pdu = self._processIncomingFrame(data[used_len:])
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/framer/base.py", line 95, in _processIncomingFrame
    used_len, dev_id, tid, frame_data = self.decode(data)
                                        ^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/framer/rtu.py", line 112, in decode
    if not (size := pdu_class.calculateRtuFrameSize(data[used_len:])):
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "(...)/.PycharmEnvironments/general/lib/python3.11/site-packages/pymodbus/pdu/mei_message.py", line 123, in calculateRtuFrameSize
    count = int(buffer[7])
                ~~~~~~^^^
IndexError: index out of range

Given that when the issue happens only 4 bytes are received and the transmission happens with DMA on a 32 bit system my first guess would be that it could be a timing issue. Any ideas on what might be causing this or how to further investigate it?

[janiversen]

Hmm looks like a bug we solved, but I will check.

[janiversen]

Bug confirmed, started with v3.7.4, and is still present on dev.

v3.7.0 - v3.7.3 have another problem, that they do not read the whole message.

A fix will be made available shortly, together with a new test case, that ensures the bug do not reappear.

[MatthiasJaeger]

Great, thank you. Happy to test here as well as soon as available.

[janiversen]

This is a more serious bug that affect the way sync reading works, it will take time to fix that.

Until then, you can try to chhange to use the async_client, it works !

[janiversen]

Fixed on dev.

[MatthiasJaeger]

Thank you. Tested the dev branch version and it works for my case.