Transmission errors through tty/pty

[t-dan]

Hello,
I am trying to make a prototype of MODBUS reader, and I use ModbusSimulatorServer to simulate the device.
However, when connecting the two sides through pty, I get Modbus Error: [Input/Output] Modbus Error: [Invalid Message] Incomplete message received, expected at least None bytes (9 received) errors - every second read but not consistent for a given type of registers. From the debug log, it seems to me that the Simulator sends the data correctly

I create the PTY pairs by socat:
socat -d -d pty,raw,echo=0 pty,raw,echo=0

In the attachments, there are codes I use.

registers.json - the registers definition
server_mock.py - the mock server; change the pty based on socat output, then run simply as python server_mock.py

MODBUS.json - the definitions of the read sequence
modbus_demo.py - the demo client; change the pty based on socat output, or uncomment the TCP variant, then run as python modbus_demo.py MODBUS.json

Let me also note that the same codes, just going through TCP, work correctly. Therefore, I guess it has something to do with RTU?

Does anyone have similar experience? Can you tell me what I did wrong?
Thank you very much
D.

[janiversen]

Socat normally works, I test with it regularly.

I use socat regularly and before making every release, so it should work. at least on linux based systems, there are known problems on windows.

If you want more help then please add a debug log, so we can see what actually happens, it looks as if your version of socat do not flush the buffers.

[janiversen]

Your error is very strange (expected none), and I am not sure how this can happen...you do no pt say if the error is on the server or client side.

Which version of pymodbus are you using ? on which platform?

[t-dan]

I use pymodbus 3.7.0 on Arch Linux.

Here are the debug outputs. From the "server":

2024-10-03 23:33:15,819 DEBUG      Using selector: EpollSelector
2024-10-03 23:33:15,835 INFO       Modbus server started on ('/dev/pts/18', 0)
2024-10-03 23:33:15,857 INFO       Modbus server started on ('0.0.0.0', 5020)
2024-10-03 23:33:15,857 DEBUG      Awaiting connections server_listener
2024-10-03 23:33:15,858 INFO       Server listening.
2024-10-03 23:33:15,858 DEBUG      Awaiting connections server_listener
2024-10-03 23:33:15,858 DEBUG      Connected to server
2024-10-03 23:33:15,858 ERROR      Error starting http server, reason: [Errno 98] error while attempting to bind on address ('0.0.0.0', 8080): address already in use
2024-10-03 23:33:15,859 INFO       HTTP server started on (0.0.0.0:8080)
2024-10-03 23:33:15,859 INFO       Server listening.
2024/10/03 23:33:30 socat[177312] N write(7, 0x5f8118530000, 8) completed
2024-10-03 23:33:30,101 DEBUG      recv: 0x1 0x4 0x0 0xa 0x0 0x1 0x11 0xc8 old_data:  addr=None
2024-10-03 23:33:30,101 DEBUG      Handling data: 0x1 0x4 0x0 0xa 0x0 0x1 0x11 0xc8
2024-10-03 23:33:30,101 DEBUG      Processing: 0x1 0x4 0x0 0xa 0x0 0x1 0x11 0xc8
2024-10-03 23:33:30,102 DEBUG      Getting Frame - 0x4 0x0 0xa 0x0 0x1
2024-10-03 23:33:30,102 DEBUG      Factory Request[ReadInputRegistersRequest': 4]
2024-10-03 23:33:30,102 DEBUG      Frame advanced, resetting header!!
2024-10-03 23:33:30,102 DEBUG      send: 0x1 0x4 0x2 0x0 0x0 0xb9 0x30
2024/10/03 23:33:30 socat[177312] N write(5, 0x5f8118530000, 7) completed
2024/10/03 23:33:31 socat[177312] N write(7, 0x5f8118530000, 8) completed
2024-10-03 23:33:31,103 DEBUG      recv: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa old_data:  addr=None
2024-10-03 23:33:31,103 DEBUG      Handling data: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
2024-10-03 23:33:31,103 DEBUG      Processing: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
2024-10-03 23:33:31,103 DEBUG      Getting Frame - 0x3 0x0 0x0 0x0 0x1
2024-10-03 23:33:31,103 DEBUG      Factory Request[ReadHoldingRegistersRequest': 3]
2024-10-03 23:33:31,103 DEBUG      Frame advanced, resetting header!!
2024-10-03 23:33:31,104 DEBUG      send: 0x1 0x3 0x2 0x0 0x0 0xb8 0x44
2024/10/03 23:33:31 socat[177312] N write(5, 0x5f8118530000, 7) completed
2024/10/03 23:33:31 socat[177312] N write(7, 0x5f8118530000, 8) completed
2024-10-03 23:33:31,230 DEBUG      recv: 0x1 0x4 0x0 0xb 0x0 0x1 0x40 0x8 old_data:  addr=None
2024-10-03 23:33:31,230 DEBUG      Handling data: 0x1 0x4 0x0 0xb 0x0 0x1 0x40 0x8
2024-10-03 23:33:31,230 DEBUG      Processing: 0x1 0x4 0x0 0xb 0x0 0x1 0x40 0x8
2024-10-03 23:33:31,230 DEBUG      Getting Frame - 0x4 0x0 0xb 0x0 0x1
2024-10-03 23:33:31,230 DEBUG      Factory Request[ReadInputRegistersRequest': 4]
2024-10-03 23:33:31,230 DEBUG      Frame advanced, resetting header!!
2024-10-03 23:33:31,231 DEBUG      send: 0x1 0x4 0x2 0x0 0x0 0xb9 0x30
2024/10/03 23:33:31 socat[177312] N write(5, 0x5f8118530000, 7) completed
2024/10/03 23:33:35 socat[177312] N write(7, 0x5f8118530000, 8) completed

And from the client:

2024-10-03 23:33:30,100 DEBUG      Current transaction state - IDLE
2024-10-03 23:33:30,100 DEBUG      Running transaction 1
2024-10-03 23:33:30,101 DEBUG      SEND: 0x1 0x4 0x0 0xa 0x0 0x1 0x11 0xc8
2024-10-03 23:33:30,101 DEBUG      Resetting frame - Current Frame in buffer - 
2024-10-03 23:33:30,101 DEBUG      New Transaction state "SENDING"
2024-10-03 23:33:30,101 DEBUG      Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-10-03 23:33:30,105 DEBUG      Transaction failed. (Modbus Error: [Invalid Message] Incomplete message received, expected at least None bytes (7 received)) 
2024-10-03 23:33:30,106 DEBUG      Processing: 
2024-10-03 23:33:30,106 DEBUG      Getting transaction 0
2024-10-03 23:33:30,106 DEBUG      Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
ERROR occured:  Modbus Error: [Input/Output] Modbus Error: [Invalid Message] Incomplete message received, expected at least None bytes (7 received)   -- reading addr: 10  nregs: 1  rtype: 4
2024-10-03 23:33:31,100 DEBUG      Current transaction state - TRANSACTION_COMPLETE
2024-10-03 23:33:31,100 DEBUG      Running transaction 2
2024-10-03 23:33:31,100 DEBUG      SEND: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
2024-10-03 23:33:31,101 DEBUG      Resetting frame - Current Frame in buffer - 
2024-10-03 23:33:31,101 DEBUG      Changing state to IDLE - Last Frame End - None Current Time stamp - 1727991211.101074
2024-10-03 23:33:31,103 DEBUG      New Transaction state "SENDING"
2024-10-03 23:33:31,103 DEBUG      Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-10-03 23:33:31,107 DEBUG      Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-10-03 23:33:31,107 DEBUG      RECV: 0x1 0x3 0x2 0x0 0x0 0xb8 0x44
2024-10-03 23:33:31,107 DEBUG      Got response!!!
2024-10-03 23:33:31,107 DEBUG      Processing: 0x1 0x3 0x2 0x0 0x0 0xb8 0x44
2024-10-03 23:33:31,108 DEBUG      Getting Frame - 0x3 0x2 0x0 0x0
2024-10-03 23:33:31,108 DEBUG      Factory Response[ReadHoldingRegistersResponse': 3]
2024-10-03 23:33:31,108 DEBUG      Frame advanced, resetting header!!
2024-10-03 23:33:31,108 DEBUG      Adding transaction 0
2024-10-03 23:33:31,108 DEBUG      Getting transaction 0
2024-10-03 23:33:31,108 DEBUG      Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
OK addr: 0  nregs: 1  rtype: 3  --  [0]
2024-10-03 23:33:31,228 DEBUG      Current transaction state - TRANSACTION_COMPLETE
2024-10-03 23:33:31,229 DEBUG      Running transaction 3
2024-10-03 23:33:31,229 DEBUG      SEND: 0x1 0x4 0x0 0xb 0x0 0x1 0x40 0x8
2024-10-03 23:33:31,229 DEBUG      Resetting frame - Current Frame in buffer - 
2024-10-03 23:33:31,229 DEBUG      Changing state to IDLE - Last Frame End - 1727991211.107682 Current Time stamp - 1727991211.229623
2024-10-03 23:33:31,229 DEBUG      New Transaction state "SENDING"
2024-10-03 23:33:31,230 DEBUG      Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-10-03 23:33:31,234 DEBUG      Transaction failed. (Modbus Error: [Invalid Message] Incomplete message received, expected at least None bytes (7 received)) 
2024-10-03 23:33:31,234 DEBUG      Processing: 
2024-10-03 23:33:31,234 DEBUG      Getting transaction 0
2024-10-03 23:33:31,234 DEBUG      Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
ERROR occured:  Modbus Error: [Input/Output] Modbus Error: [Invalid Message] Incomplete message received, expected at least None bytes (7 received)   -- reading addr: 11  nregs: 1  rtype: 4
2024-10-03 23:33:35,100 DEBUG      Current transaction state - TRANSACTION_COMPLETE
2024-10-03 23:33:35,100 DEBUG      Running transaction 4
2024-10-03 23:33:35,100 DEBUG      SEND: 0x1 0x4 0x0 0x0 0x0 0x6 0x70 0x8
2024-10-03 23:33:35,101 DEBUG      Resetting frame - Current Frame in buffer - 
2024-10-03 23:33:35,101 DEBUG      Changing state to IDLE - Last Frame End - None Current Time stamp - 1727991215.101057
2024-10-03 23:33:35,103 DEBUG      New Transaction state "SENDING"
2024-10-03 23:33:35,103 DEBUG      Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-10-03 23:33:35,107 DEBUG      Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-10-03 23:33:35,107 DEBUG      RECV: 0x1 0x4 0xc 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x95 0xb7
2024-10-03 23:33:35,107 DEBUG      Got response!!!
2024-10-03 23:33:35,107 DEBUG      Processing: 0x1 0x4 0xc 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x95 0xb7
2024-10-03 23:33:35,108 DEBUG      Getting Frame - 0x4 0xc 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0
2024-10-03 23:33:35,108 DEBUG      Factory Response[ReadInputRegistersResponse': 4]
2024-10-03 23:33:35,108 DEBUG      Frame advanced, resetting header!!
2024-10-03 23:33:35,108 DEBUG      Adding transaction 0
2024-10-03 23:33:35,108 DEBUG      Getting transaction 0
2024-10-03 23:33:35,108 DEBUG      Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
OK addr: 0  nregs: 6  rtype: 4  --  [0, 0, 0, 0, 0, 0]

Hope it helps a bit ...
Thank you.

[t-dan]

The version of socat is this:

socat by Gerhard Rieger and contributors - see www.dest-unreach.org
socat version 1.8.0.0 on 08 Jun 2024 18:07:14
   running on Linux version #1 SMP PREEMPT_DYNAMIC Sun, 11 Aug 2024 16:19:06 +0000, release 6.10.4-arch2-1, machine x86_64
features:
  #define WITH_HELP 1
  #define WITH_STATS 1
  #define WITH_STDIO 1
  #define WITH_FDNUM 1
  #define WITH_FILE 1
  #define WITH_CREAT 1
  #define WITH_GOPEN 1
  #define WITH_TERMIOS 1
  #define WITH_PIPE 1
  #define WITH_SOCKETPAIR 1
  #define WITH_UNIX 1
  #define WITH_ABSTRACT_UNIXSOCKET 1
  #define WITH_IP4 1
  #define WITH_IP6 1
  #define WITH_RAWIP 1
  #define WITH_GENERICSOCKET 1
  #define WITH_INTERFACE 1
  #define WITH_TCP 1
  #define WITH_UDP 1
  #define WITH_SCTP 1
  #define WITH_DCCP 1
  #define WITH_UDPLITE 1
  #define WITH_LISTEN 1
  #define WITH_POSIXMQ 1
  #define WITH_SOCKS4 1
  #define WITH_SOCKS4A 1
  #define WITH_SOCKS5 1
  #define WITH_VSOCK 1
  #define WITH_NAMESPACES 1
  #define WITH_PROXY 1
  #define WITH_SYSTEM 1
  #define WITH_SHELL 1
  #define WITH_EXEC 1
  #define WITH_READLINE 1
  #define WITH_TUN 1
  #define WITH_PTY 1
  #define WITH_OPENSSL 1
  #undef WITH_FIPS
  #undef WITH_LIBWRAP
  #define WITH_SYCLS 1
  #define WITH_FILAN 1
  #define WITH_RETRY 1
  #define WITH_MSGLEVEL 0 /*debug*/
  #define WITH_DEFAULT_IPV 0

[janiversen]

Thanks I will take a closer look later.

[janiversen]

Please try with newest dev, #2353 should solve your problem.

You forgot to mention that you use the sync client, that threw me off track. Please be aware that the async client can handle a lot more requests/responses pr second.

[t-dan]

I do confirm that with the change it works without errors.
Thank you!

[janiversen]

Log analysis:

CLIENT -> SOCAT -> SERVER -> SOCAT -> CLIENT

CLIENT 23:33:30,101 SEND: 0x1 0x4 0x0 0xa 0x0 0x1 0x11 0xc8
SOCAT  23:33:30     write 8
SERVER 23:33:30,101 recv: 0x1 0x4 0x0 0xa 0x0 0x1 0x11 0xc8 old_data:  addr=None
SERVER 23:33:30,102 send: 0x1 0x4 0x2 0x0 0x0 0xb9 0x30
SOCAT  23:33:30     write 7
CLIENT 23:33:30,105 Incomplete message received, expected at least None bytes (7 received))

CLIENT 23:33:31,100 SEND: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
SOCAT  23:33:31     write 8
SERVER 23:33:31,103 recv: 0x1 0x3 0x0 0x0 0x0 0x1 0x84 0xa
SERVER 23:33:31,104 send: 0x1 0x3 0x2 0x0 0x0 0xb8 0x44
SOCAT  23:33:31     write 7
CLIENT 23:33:31,107 RECV: 0x1 0x3 0x2 0x0 0x0 0xb8 0x44

CLIENT 23:33:31,229 SEND: 0x1 0x4 0x0 0xb 0x0 0x1 0x40 0x8
SOCAT  23:33:31     write 8
SERVER 23:33:31,230 recv: 0x1 0x4 0x0 0xb 0x0 0x1 0x40 0x8
SERVER 23:33:31,231 send: 0x1 0x4 0x2 0x0 0x0 0xb9 0x30
SOCAT  23:33:31     write 7
CLIENT 23:33:31,234 Incomplete message received, expected at least None bytes (7 received))