Forwarder example sends each request twice

[TheChatty]

Versions

• Python: 3.10.5
• OS: Windows 11 x64
• Pymodbus: 1.5.2, 2.5.3, 3.0.0.dev4
• Modbus Hardware (if used):

Pymodbus Specific

• Server: tcp/rtu/ascii - sync/async
• Client: tcp/rtu/ascii - sync/async

Description

Running the forwarder example with tcp slave and tcp server each request to the server is sent twice to the slave when it should be sent once.

Code and Logs

For testing purposed I created the forwarder like this (unit 248 --> 247):

context = ModbusServerContext(slaves={248: RemoteSlaveContext(client, unit=247)}, single=False)

Now when a client asks the forwarder to read first holding register, this is what happens at the forwarder:

 # code and logs here.
03:59:19,280 MainThread DEBUG    sync           :215      Connection to Modbus server established. Socket ('192.168.178.53', 52413)
04:05:06,214 MainThread DEBUG    sync           :348      Started thread to serve client at ('127.0.0.1', 52754)
04:05:06,214 Thread-1 ( DEBUG    sync           :46       Client Connected [127.0.0.1:52754]
04:05:06,214 Thread-1 ( DEBUG    sync           :199      Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0xf8 0x3 0x0 0x0 0x0 0x1
04:05:06,214 Thread-1 ( DEBUG    socket_framer  :147      Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0xf8 0x3 0x0 0x0 0x0 0x1
04:05:06,214 Thread-1 ( DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
04:05:06,214 Thread-1 ( DEBUG    remote         :42       validate[3] 0:1
04:05:06,214 Thread-1 ( DEBUG    transaction    :139      Current transaction state - IDLE
04:05:06,214 Thread-1 ( DEBUG    transaction    :144      Running transaction 1
04:05:06,214 Thread-1 ( DEBUG    transaction    :273      SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0xf7 0x3 0x0 0x0 0x0 0x1
04:05:06,214 Thread-1 ( DEBUG    sync           :76       New Transaction state 'SENDING'
04:05:06,214 Thread-1 ( DEBUG    transaction    :287      Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
04:05:06,399 Thread-1 ( DEBUG    transaction    :375      Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
04:05:06,399 Thread-1 ( DEBUG    transaction    :297      RECV: 0x0 0x1 0x0 0x0 0x0 0x5 0xf7 0x3 0x2 0x15 0xc5
04:05:06,399 Thread-1 ( DEBUG    socket_framer  :147      Processing: 0x0 0x1 0x0 0x0 0x0 0x5 0xf7 0x3 0x2 0x15 0xc5
04:05:06,399 Thread-1 ( DEBUG    factory        :266      Factory Response[ReadHoldingRegistersResponse: 3]
04:05:06,399 Thread-1 ( DEBUG    transaction    :454      Adding transaction 1
04:05:06,399 Thread-1 ( DEBUG    transaction    :465      Getting transaction 1
04:05:06,399 Thread-1 ( DEBUG    transaction    :224      Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
04:05:06,399 Thread-1 ( DEBUG    remote         :55       get values[3] 0:1
04:05:06,399 Thread-1 ( DEBUG    transaction    :139      Current transaction state - TRANSACTION_COMPLETE
04:05:06,399 Thread-1 ( DEBUG    transaction    :144      Running transaction 2
04:05:06,399 Thread-1 ( DEBUG    transaction    :273      SEND: 0x0 0x2 0x0 0x0 0x0 0x6 0xf7 0x3 0x0 0x0 0x0 0x1
04:05:06,399 Thread-1 ( DEBUG    sync           :76       New Transaction state 'SENDING'
04:05:06,399 Thread-1 ( DEBUG    transaction    :287      Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
04:05:06,524 Thread-1 ( DEBUG    transaction    :375      Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
04:05:06,524 Thread-1 ( DEBUG    transaction    :297      RECV: 0x0 0x2 0x0 0x0 0x0 0x5 0xf7 0x3 0x2 0x15 0xc5
04:05:06,524 Thread-1 ( DEBUG    socket_framer  :147      Processing: 0x0 0x2 0x0 0x0 0x0 0x5 0xf7 0x3 0x2 0x15 0xc5
04:05:06,524 Thread-1 ( DEBUG    factory        :266      Factory Response[ReadHoldingRegistersResponse: 3]
04:05:06,524 Thread-1 ( DEBUG    transaction    :454      Adding transaction 2
04:05:06,524 Thread-1 ( DEBUG    transaction    :465      Getting transaction 2
04:05:06,524 Thread-1 ( DEBUG    transaction    :224      Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
04:05:06,524 Thread-1 ( DEBUG    sync           :229      send: [ReadHoldingRegistersResponse (1)]- b'000100000005f8030215c5'
04:05:06,540 Thread-1 ( DEBUG    sync           :199      Handling data:
04:05:06,540 Thread-1 ( DEBUG    socket_framer  :147      Processing:
04:05:06,540 Thread-1 ( DEBUG    sync           :54       Client Disconnected [127.0.0.1:52754]

I can confirm the actual slave receives the request twice as well. This is true for pymodbus 1.5.2, 2.5.3 as well as 3.0.0.dev4.

[janiversen]

I will take a look later, but it seems a bit like you have a duplicate in your code.

[TheChatty]

duplicates.py.zip

This minimal solution prooves my point.

[janiversen]

thanks that will do for a fine test case.

[janiversen]

Your example crashes on current dev:

Exception in thread Thread-1 (run_fake_server):
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/threading.py", line 1009, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/jan/repos/pymodbus/examples/duplicates.py", line 33, in run_fake_server
    StartServer(context, address=("", 5020), unit=247)
  File "/Users/jan/repos/pymodbus/pymodbus/server/sync.py", line 659, in StartTcpServer
    server = ModbusTcpServer(context, framer, identity, address, **kwargs)
  File "/Users/jan/repos/pymodbus/pymodbus/server/sync.py", line 363, in __init__
    socketserver.ThreadingTCPServer.__init__(
TypeError: TCPServer.__init__() got an unexpected keyword argument 'unit'
11:21:25 DEBUG sync:230 Connection to Modbus server established. Socket ('127.0.0.1', 59753)
11:21:25 DEBUG sync:388 Modbus server stopped
Exception in thread Thread-2 (run_tcp_forwarder):
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/threading.py", line 1009, in _bootstrap_inner
    self.run()
  File "/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/jan/repos/pymodbus/examples/duplicates.py", line 23, in run_tcp_forwarder
    StartServer(context, address=("localhost", 5010))
  File "/Users/jan/repos/pymodbus/pymodbus/server/sync.py", line 659, in StartTcpServer
    server = ModbusTcpServer(context, framer, identity, address, **kwargs)
  File "/Users/jan/repos/pymodbus/pymodbus/server/sync.py", line 363, in __init__
    socketserver.ThreadingTCPServer.__init__(
  File "/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/socketserver.py", line 452, in __init__
    self.server_bind()
  File "/Library/Frameworks/Python.framework/Versions/3.10/lib/python3.10/socketserver.py", line 466, in server_bind
    self.socket.bind(self.server_address)
OSError: [Errno 48] Address already in use
11:21:26 ERROR sync:233 Connection to (localhost, 5010) failed: [Errno 61] Connection refused
11:21:26 ERROR sync:233 Connection to (localhost, 5010) failed: [Errno 61] Connection refused
Traceback (most recent call last):
  File "/Users/jan/repos/pymodbus/examples/duplicates.py", line 46, in <module>
    rr = client.read_holding_registers(0, 1, unit=248)
  File "/Users/jan/repos/pymodbus/pymodbus/client/common.py", line 118, in read_holding_registers
    return self.execute(request)  # pylint: disable=no-member
  File "/Users/jan/repos/pymodbus/pymodbus/client/sync.py", line 123, in execute
    raise ConnectionException(f"Failed to connect[{str(self)}]")
pymodbus.exceptions.ConnectionException: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(localhost:5010)]

[TheChatty]

There was a wrong unit definition. Since it's a "single" server it's not necessary anyways. Here's the corrected example proving my point even with pymodbus==3.0.0.dev4.
duplicates.py.zip

[janiversen]

It is a bit complicated to see in the log, which part sends what, but it seems very suspicious, I will investigate further.

Thanks for the code, it works nicely.

[janiversen]

There are at least one problem with your code. You cannot have 2 servers within the same process! the library currently use a singleton to secure access to some common data, which means the 2 servers shares data. This is bound to cause some problems.

I tried the example a bit different (but more realistic):

# start fake server
server_sync.py --port=5010 &
# start forwarder (server+client interconnected)
forwarder.py 
# start client that does read_holding_registers
client_sync.py --port=5020

As far as I can see from a simple test, it works.

[TheChatty]

My setup is as follows:

• A: Real modbus client (Trovis 5573, not that it matters) offering TX/RX and RTU protocol
• B: ESP8266 running Tasmota to offer either plain TCP serial bridge or modbus TCP to RTU bridge
• C: pymodbus forwarder local TCP to Tasmota TCP or RTU bridge
• D: local pymodbus TCP client

D -> C -> B -> A

This setup IS working... but each request from D is sent twice by C. And it seems to be a race condition. The following log from C was produced without changing anything... first time it was sent once, second it was sent twice.
race_cond.txt

[janiversen]

You could avoid B and go directly C -> A.

Now at least I understand your problem, let me make a more stable test bed so I can pass 1.000 or more requests.

I fear it can be something internal in the datastore.

Thanks for your patience.

[TheChatty]

A & B are located in the basement whereas C & D are on my laptop upstairs. D shall be replaced with vendor-specific client (TrovisView). But B is not robust yet for huge consecutive requests - I need to analyze this once this pymodbus problem is solved.

[janiversen]

I hate these days!!!! There are clearly an error in datastore, the forwarder DO SEND DUPLICATES.

I have made an updated forwarder (but it is still not working correctly).

Can you help me a bit here, do you address multiple slaves on D (the device level) or are you passing information about only 1 device ?

[TheChatty]

There is only one real device involved (A listening to unit id 247). And it's the only device I'm addressing in this bug in the whole chain (D to A). Why is the forwarder storing any values at all if each request is forwarded?

Btw: I want to extend the forwarder example to an intermittent proxy which explains every read register in the log ("read device type, wrote 5573" for instance).

[janiversen]

After a long research, I can now confirm what happens and why.

You see 2 requests being sent to the device, but they are not identical.
f.x. you do write_register.
That will send a write_register request to your device, and then a read_request
if you do a read_register
That will send 2 read_register requests.

Both are done in order to be able to return the updated values in the device.

Normally a device does:
a) receive a write request.
b) execute the request.
c) update the memory image
d) return the updated value(s)

In order for the repeater to do d) it needs to send a read request to simulate c).