search

pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.22k stars 907 forks source link

ModbusUdpClient with retry_on_invalid=True always retries #1929

Closed MAKOMO closed 7 months ago

MAKOMO commented 7 months ago

Versions

Pymodbus Specific

Description

A ModbusUdpClient with retry_on_invalid=True and retries=n seems to retry exactly n times in any case.

Code and Logs

The following server serves one register value via UDP on localhost and prints a line on each received request for data.

server.py

import time
from pymodbus.server import StartUdpServer
from pymodbus.datastore import ModbusSparseDataBlock
from pymodbus.datastore import ModbusSlaveContext, ModbusServerContext

import pymodbus
pymodbus.pymodbus_apply_logging_config("DEBUG")

class CallbackDataBlock(ModbusSparseDataBlock):
    def __init__(self, values):
        super(CallbackDataBlock, self).__init__(values)
    def getValues(self,address, count=1):
        print(time.asctime(),"getValues",address,count)
        return super(CallbackDataBlock, self).getValues(address, count)

block = CallbackDataBlock({1: 200})
store = ModbusSlaveContext(ir = block)
context = ModbusServerContext(slaves=store, single=True)
StartUdpServer(context=context, address=("127.0.0.1", 502))

Accessing this server with the following client with 3 retries and retry_on_invalid=True

import pymodbus
pymodbus.pymodbus_apply_logging_config("DEBUG")

from pymodbus.client import ModbusUdpClient
master = ModbusUdpClient(
    host="127.0.0.1",
    port=502,
    retries=3,
    retry_on_invalid=True)

master.connect()
res = master.read_input_registers(0,slave=1)
if res.isError():
    print("error")
else:
    print("registers",res.registers)

receives the register value correctly and prints showing the retries happening, which is strange as there is actually no failure accessing that register from the server running locally as can see if one starts the client with retry_on_invalid=True or retries=0.

2024-01-12 08:32:26,384 DEBUG logging:103 Current transaction state - IDLE
2024-01-12 08:32:26,384 DEBUG logging:103 Running transaction 1
2024-01-12 08:32:26,384 DEBUG logging:103 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:32:26,384 DEBUG logging:103 New Transaction state "SENDING"
2024-01-12 08:32:26,385 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-01-12 08:32:26,402 DEBUG logging:103 Incomplete message received, Expected 1024 bytes Received 11 bytes !!!!
2024-01-12 08:32:26,402 DEBUG logging:103 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-01-12 08:32:26,402 DEBUG logging:103 RECV: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:32:26,403 DEBUG logging:103 Retry on invalid response - 3
2024-01-12 08:32:26,403 DEBUG logging:103 Changing transaction state from "WAITING_FOR_REPLY" to "RETRYING"
2024-01-12 08:32:26,706 DEBUG logging:103 Sleeping 0.3
2024-01-12 08:32:26,706 DEBUG logging:103 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:32:26,706 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-01-12 08:32:26,708 DEBUG logging:103 Incomplete message received, Expected 1024 bytes Received 11 bytes !!!!
2024-01-12 08:32:26,708 DEBUG logging:103 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-01-12 08:32:26,708 DEBUG logging:103 RECV: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:32:26,708 DEBUG logging:103 Retry on invalid response - 2
2024-01-12 08:32:26,708 DEBUG logging:103 Changing transaction state from "WAITING_FOR_REPLY" to "RETRYING"
2024-01-12 08:32:27,313 DEBUG logging:103 Sleeping 0.6
2024-01-12 08:32:27,313 DEBUG logging:103 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:32:27,313 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-01-12 08:32:27,314 DEBUG logging:103 Incomplete message received, Expected 1024 bytes Received 11 bytes !!!!
2024-01-12 08:32:27,314 DEBUG logging:103 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-01-12 08:32:27,314 DEBUG logging:103 RECV: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:32:27,315 DEBUG logging:103 Retry on invalid response - 1
2024-01-12 08:32:27,315 DEBUG logging:103 Changing transaction state from "WAITING_FOR_REPLY" to "RETRYING"

2024-01-12 08:32:28,516 DEBUG logging:103 Sleeping 1.2
2024-01-12 08:32:28,516 DEBUG logging:103 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:32:28,516 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-01-12 08:32:28,521 DEBUG logging:103 Incomplete message received, Expected 1024 bytes Received 11 bytes !!!!
2024-01-12 08:32:28,521 DEBUG logging:103 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-01-12 08:32:28,522 DEBUG logging:103 RECV: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:32:28,522 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:32:28,522 DEBUG logging:103 Factory Response[ReadInputRegistersResponse': 4]
2024-01-12 08:32:28,522 DEBUG logging:103 Adding transaction 1
2024-01-12 08:32:28,522 DEBUG logging:103 Getting transaction 1
2024-01-12 08:32:28,522 DEBUG logging:103 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
registers [200]

On the server it logs 4 reads for this one client request:

# sudo python3 server.py
2024-01-11 22:13:30,092 DEBUG logging:103 Awaiting connections server_listener
2024-01-11 22:13:30,092 DEBUG logging:103 Connected to server
2024-01-11 22:13:30,093 INFO  logging:97 Server listening.
2024-01-11 22:13:39,255 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1 old_data:  addr=('127.0.0.1', 53070)
2024-01-11 22:13:39,255 DEBUG logging:103 Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:39,256 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:39,256 DEBUG logging:103 Factory Request[ReadInputRegistersRequest': 4]
2024-01-11 22:13:39,256 DEBUG logging:103 validate: fc-[4] address-1: count-1
2024-01-11 22:13:39,256 DEBUG logging:103 getValues: fc-[4] address-1: count-1
Thu Jan 11 22:13:39 2024 getValues 1 1
2024-01-11 22:13:39,256 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-11 22:13:39,560 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1 old_data:  addr=('127.0.0.1', 53070)
2024-01-11 22:13:39,560 DEBUG logging:103 Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:39,560 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:39,560 DEBUG logging:103 Factory Request[ReadInputRegistersRequest': 4]
2024-01-11 22:13:39,560 DEBUG logging:103 validate: fc-[4] address-1: count-1
2024-01-11 22:13:39,560 DEBUG logging:103 getValues: fc-[4] address-1: count-1
Thu Jan 11 22:13:39 2024 getValues 1 1
2024-01-11 22:13:39,561 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-11 22:13:40,162 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1 old_data:  addr=('127.0.0.1', 53070)
2024-01-11 22:13:40,162 DEBUG logging:103 Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:40,162 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:40,162 DEBUG logging:103 Factory Request[ReadInputRegistersRequest': 4]
2024-01-11 22:13:40,162 DEBUG logging:103 validate: fc-[4] address-1: count-1
2024-01-11 22:13:40,162 DEBUG logging:103 getValues: fc-[4] address-1: count-1
Thu Jan 11 22:13:40 2024 getValues 1 1
2024-01-11 22:13:40,163 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-11 22:13:41,366 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1 old_data:  addr=('127.0.0.1', 53070)
2024-01-11 22:13:41,367 DEBUG logging:103 Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:41,367 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-11 22:13:41,367 DEBUG logging:103 Factory Request[ReadInputRegistersRequest': 4]
2024-01-11 22:13:41,367 DEBUG logging:103 validate: fc-[4] address-1: count-1
2024-01-11 22:13:41,367 DEBUG logging:103 getValues: fc-[4] address-1: count-1
Thu Jan 11 22:13:41 2024 getValues 1 1
2024-01-11 22:13:41,367 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8

With retry_on_invalid=False or using the TCP client and server, just one request is received by the server.

UDP client output with client configured using retry_on_invalid=False (just one request sent without any retry, which completed without returning an error returning the correct result):

2024-01-12 08:39:17,844 DEBUG logging:103 Current transaction state - IDLE
2024-01-12 08:39:17,844 DEBUG logging:103 Running transaction 1
2024-01-12 08:39:17,845 DEBUG logging:103 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:39:17,845 DEBUG logging:103 New Transaction state "SENDING"
2024-01-12 08:39:17,845 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-01-12 08:39:17,846 DEBUG logging:103 Incomplete message received, Expected 1024 bytes Received 11 bytes !!!!
2024-01-12 08:39:17,846 DEBUG logging:103 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-01-12 08:39:17,846 DEBUG logging:103 RECV: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:39:17,846 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8
2024-01-12 08:39:17,847 DEBUG logging:103 Factory Response[ReadInputRegistersResponse': 4]
2024-01-12 08:39:17,847 DEBUG logging:103 Adding transaction 1
2024-01-12 08:39:17,847 DEBUG logging:103 Getting transaction 1
2024-01-12 08:39:17,847 DEBUG logging:103 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
registers [200]

UDP server output with client configured using retry_on_invalid=False (just one request received and answered):

2024-01-12 08:38:59,787 DEBUG logging:103 Awaiting connections server_listener
2024-01-12 08:38:59,787 DEBUG logging:103 Connected to server
2024-01-12 08:38:59,787 INFO  logging:97 Server listening.
2024-01-12 08:39:17,845 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1 old_data:  addr=('127.0.0.1', 60040)
2024-01-12 08:39:17,845 DEBUG logging:103 Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:39:17,845 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x4 0x0 0x0 0x0 0x1
2024-01-12 08:39:17,846 DEBUG logging:103 Factory Request[ReadInputRegistersRequest': 4]
2024-01-12 08:39:17,846 DEBUG logging:103 validate: fc-[4] address-1: count-1
2024-01-12 08:39:17,846 DEBUG logging:103 getValues: fc-[4] address-1: count-1
Fri Jan 12 08:39:17 2024 getValues 1 1
2024-01-12 08:39:17,846 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x5 0x1 0x4 0x2 0x0 0xc8

This behavior can be observed with pymodbus v3.3.1 and newer. For pymodbus v3.0.2 and earlier just one request is received by a client with retry_on_invalid=True.

janiversen commented 7 months ago

I am not sure I understand what the problem is? reading the description the behavior is what I expected.

Please make it a bit clearer what does not work as expected.

MAKOMO commented 7 months ago

Shouldn't client retries only happen on errors? Here there is a communication without error and still it takes always all retries while the first request already succeeds.

MAKOMO commented 7 months ago

I added the debug configuration also to the client and added also the debug output for the client. Interestingly, even on retry_on_invalid=False there is an internal Incomplete message received, Expected 1024 bytes Received 11 bytes !!!! while the correct result is still returned without an error. Is this really the behavior that you expected?

janiversen commented 7 months ago

It depends whether the 11 bytes is a valid message, let me check.

And yes retry is only on errors.