search

pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.16k stars 889 forks source link

ssl.SSLWantReadError: The operation did not complete (read) when using ModbusTlsClient #2184

Closed VDigitall closed 1 month ago

VDigitall commented 1 month ago

Versions

Pymodbus Specific

Description

I'm starting the async tls modbus server using certificates from the example folder and function StartAsyncTlsServer with defining a few slaves. After that, I tried to read some slaves using the client (ModbusTlsClient) and received the exception Modbus Error: The operation did not complete (read) (_ssl.c:2633). I read slave 1 python client.py --slave_id 1 --address 0 --count 1

Code and Logs

Client code is following:

import argparse
import pymodbus
from pymodbus.client import ModbusTcpClient, ModbusTlsClient
from pymodbus.exceptions import ConnectionException, ModbusIOException

pymodbus.pymodbus_apply_logging_config("DEBUG")

def main():
    parser = argparse.ArgumentParser(description="Modbus client")
    parser.add_argument("--write", action="store_true", help="Write mode")
    parser.add_argument("--host", type=str, help="Host", default="localhost")
    parser.add_argument("--port", type=int, help="Port", default=502)
    parser.add_argument("--slave_id", type=int, help="Slave ID")
    parser.add_argument("--address", type=int, help="Address")
    parser.add_argument("--count", type=int, help="Count of registers to read", default=1)
    parser.add_argument("--value", type=int, help="Value to write", default=0)

    args = parser.parse_args()
    try:
        client = ModbusTlsClient(
            args.host,
            args.port,
            certfile="certificates/pymodbus.crt",
            keyfile="certificates/pymodbus.key",
            server_hostname="localhost",
        )
        client.connect()
        if args.write:
            result = client.write_register(args.address, args.value, slave=args.slave_id)
        else:
            result = client.read_holding_registers(args.address, args.count, slave=args.slave_id)
        if result.isError():
            print(f"ModbusClient Error, the id {args.slave_id} or address {args.address} is invalid")
            print(result)
            return
    except (ConnectionException, ModbusIOException) as e:
        print(f"Error connecting to {args.host}:{args.port} ({str(e)})")
        return
    print("Results:")
    print(result.registers)

if __name__ == "__main__":
    main()

Server logs

2024-05-02 12:13:16,849 DEBUG logging:103 Awaiting connections server_listener
2024-05-02 12:13:16,850 INFO  logging:97 Server listening.
2024-05-02 12:13:29,453 DEBUG logging:103 Connected to server
2024-05-02 12:13:29,453 DEBUG logging:103 recv: 0x3 0x0 0x0 0x0 0x1 old_data:  addr=None
2024-05-02 12:13:29,453 DEBUG logging:103 Handling data: 0x3 0x0 0x0 0x0 0x1
2024-05-02 12:13:29,453 DEBUG logging:103 Processing: 0x3 0x0 0x0 0x0 0x1
2024-05-02 12:13:29,453 DEBUG logging:103 Factory Request[ReadHoldingRegistersRequest': 3]
2024-05-02 12:13:29,454 ERROR logging:115 requested slave does not exist: 0
2024-05-02 12:13:29,454 ERROR logging:115 Exception response Exception Response(131, 3, GatewayNoResponse)
2024-05-02 12:13:29,454 DEBUG logging:103 send: 0x83 0xb
2024-05-02 12:13:29,454 DEBUG logging:103 -> transport: received eof
2024-05-02 12:13:29,454 DEBUG logging:103 Connection lost server due to None
2024-05-02 12:13:29,454 DEBUG logging:103 Handler for stream [server] has been canceled

Client logs

2024-05-02 12:13:29,453 DEBUG logging:103 Current transaction state - IDLE
2024-05-02 12:13:29,453 DEBUG logging:103 Running transaction 1
2024-05-02 12:13:29,453 DEBUG logging:103 SEND: 0x3 0x0 0x0 0x0 0x1
2024-05-02 12:13:29,453 DEBUG logging:103 New Transaction state "SENDING"
2024-05-02 12:13:29,453 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-05-02 12:13:29,453 DEBUG logging:103 Transaction failed. (The operation did not complete (read) (_ssl.c:2633))
Traceback (most recent call last):
  File "client.py", line 43, in <module>
    main()
  File "client.py", line 30, in main
    result = client.read_holding_registers(args.address, args.count, slave=args.slave_id)
  File ".venv/lib/python3.9/site-packages/pymodbus/client/mixin.py", line 107, in read_holding_registers
    return self.execute(
  File ".venv/lib/python3.9/site-packages/pymodbus/client/base.py", line 396, in execute
    return self.transaction.execute(request)
  File ".venv/lib/python3.9/site-packages/pymodbus/transaction.py", line 180, in execute
    response, last_exception = self._transact(
  File ".venv/lib/python3.9/site-packages/pymodbus/transaction.py", line 326, in _transact
    result = self._recv(response_length, full)
  File ".venv/lib/python3.9/site-packages/pymodbus/transaction.py", line 357, in _recv
    read_min = self.client.framer.recvPacket(min_size)
  File ".venv/lib/python3.9/site-packages/pymodbus/framer/base.py", line 79, in recvPacket
    return self.client.recv(size)
  File ".venv/lib/python3.9/site-packages/pymodbus/client/tcp.py", line 236, in recv
    if (recv_data := self.socket.recv(recv_size)) == b"":
  File "/Users/vmartyniak/.pyenv/versions/3.9.9/lib/python3.9/ssl.py", line 1227, in recv
    return self.read(buflen)
  File "/Users/vmartyniak/.pyenv/versions/3.9.9/lib/python3.9/ssl.py", line 1101, in read
    return self._sslobj.read(len)
ssl.SSLWantReadError: The operation did not complete (read) (_ssl.c:2633)
janiversen commented 1 month ago

Seems you are addressing a slave that do not exist:

requested slave does not exist: 0

so the server sends an exception response.

the client sees slave_id as broadcast therefore it demands a proper response with the length, however it receives an exception which is a lot shorter, and thus closes the connection and raises an exception.

So in total please try with slave_ids that are defined.

VDigitall commented 1 month ago

I was trying all defined slave_id but the server doesn't recognize its value. It always tries to get values from slave id 0, it looks like the server doesn't receive correctly slave id.

janiversen commented 1 month ago

Did you define the slave content ? without that the server does not know the client, Please see our examples,

janiversen commented 1 month ago

slave_id is broadcast, which the server must accept if it only have one slave defined, not accepting that signals you did not define any slaves in the server.

janiversen commented 1 month ago

I mean id=0 is special because its broadcast

VDigitall commented 1 month ago

@janiversen thanks for your assistance.

Did you define the slave content ? without that the server does not know the client, Please see our examples,

Yes, I defined a content for each slave Also, I was able to reproduce that issue with examples too.

I have a problem only when using TLS (Modbus Error: The operation did not complete (read) (_ssl.c:2633) Without TLS everything works well.

janiversen commented 1 month ago

Yes because you cannot use slave id 0 !

VDigitall commented 1 month ago

I don't use slave id 0 There are logs when I run command python client.py --slave_id 1 --address 0 --count 1

2024-05-02 12:13:29,453 DEBUG logging:103 Current transaction state - IDLE
2024-05-02 12:13:29,453 DEBUG logging:103 Running transaction 1
2024-05-02 12:13:29,453 DEBUG logging:103 SEND: 0x3 0x0 0x0 0x0 0x1
2024-05-02 12:13:29,453 DEBUG logging:103 New Transaction state "SENDING"
2024-05-02 12:13:29,453 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-05-02 12:13:29,453 DEBUG logging:103 Transaction failed. (The operation did not complete (read) (_ssl.c:2633))

and logs when I run python client.py --slave_id 2 --address 0 --count 1

2024-05-02 19:39:01,957 DEBUG logging:103 Current transaction state - IDLE
2024-05-02 19:39:01,958 DEBUG logging:103 Running transaction 1
2024-05-02 19:39:01,958 DEBUG logging:103 SEND: 0x3 0x0 0x0 0x0 0x1
2024-05-02 19:39:01,958 DEBUG logging:103 New Transaction state "SENDING"
2024-05-02 19:39:01,958 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-05-02 19:39:01,958 DEBUG logging:103 Transaction failed. (The operation did not complete (read) (_ssl.c:2633))

It always sends the same packet.

janiversen commented 1 month ago

Please add the server log.

janiversen commented 1 month ago

It is correct it is the same packet, BUT the client code behaves differently with broadcast than with real ids.

If the server log still contains "requested slave does not exist" then something is wrong on the server side.

VDigitall commented 1 month ago

Please add the server log.

python client.py --slave_id 3 --address 1 --count 1

2024-05-02 20:45:39,749 DEBUG logging:103 Awaiting connections server_listener
2024-05-02 20:45:39,750 INFO  logging:97 Server listening.
2024-05-02 20:46:39,216 DEBUG logging:103 Connected to server
2024-05-02 20:46:39,217 DEBUG logging:103 recv: 0x3 0x0 0x1 0x0 0x1 old_data:  addr=None
2024-05-02 20:46:39,217 DEBUG logging:103 Handling data: 0x3 0x0 0x1 0x0 0x1
2024-05-02 20:46:39,217 DEBUG logging:103 Processing: 0x3 0x0 0x1 0x0 0x1
2024-05-02 20:46:39,217 DEBUG logging:103 Factory Request[ReadHoldingRegistersRequest': 3]
2024-05-02 20:46:39,217 ERROR logging:115 requested slave does not exist: 0
2024-05-02 20:46:39,217 ERROR logging:115 Exception response Exception Response(131, 3, GatewayNoResponse)
2024-05-02 20:46:39,217 DEBUG logging:103 send: 0x83 0xb
2024-05-02 20:46:39,217 DEBUG logging:103 -> transport: received eof
2024-05-02 20:46:39,217 DEBUG logging:103 Connection lost server due to None
2024-05-02 20:46:39,217 DEBUG logging:103 Handler for stream [server] has been canceled

python client.py --slave_id 4 --address 1 --count 1

2024-05-02 20:53:54,304 DEBUG logging:103 Connected to server
2024-05-02 20:53:54,305 DEBUG logging:103 recv: 0x3 0x0 0x1 0x0 0x1 old_data:  addr=None
2024-05-02 20:53:54,305 DEBUG logging:103 Handling data: 0x3 0x0 0x1 0x0 0x1
2024-05-02 20:53:54,305 DEBUG logging:103 Processing: 0x3 0x0 0x1 0x0 0x1
2024-05-02 20:53:54,305 DEBUG logging:103 Factory Request[ReadHoldingRegistersRequest': 3]
2024-05-02 20:53:54,305 ERROR logging:115 requested slave does not exist: 0
2024-05-02 20:53:54,305 ERROR logging:115 Exception response Exception Response(131, 3, GatewayNoResponse)
2024-05-02 20:53:54,305 DEBUG logging:103 send: 0x83 0xb
2024-05-02 20:53:54,305 DEBUG logging:103 -> transport: received eof
2024-05-02 20:53:54,305 DEBUG logging:103 Connection lost server due to None
2024-05-02 20:53:54,305 DEBUG logging:103 Handler for stream [server] has been canceled
janiversen commented 1 month ago

I just made a test, and the server is responding correctly, The "requested slave does not exist" suggest you have done something wrong with the content definition.

My server log (example is unmodified)

(pymodbus) jan@OldMacMini examples % ./server_async.py --log debug --comm tls
2024-05-02 20:54:03,125 DEBUG logging:103 Awaiting connections server_listener
2024-05-02 20:54:03,127 INFO  logging:97 Server listening.
2024-05-02 20:54:17,936 DEBUG logging:103 Connected to server
2024-05-02 20:54:17,936 DEBUG logging:103 recv: 0x1 0x0 0x20 0x0 0x1 old_data:  addr=None
2024-05-02 20:54:17,936 DEBUG logging:103 Handling data: 0x1 0x0 0x20 0x0 0x1
2024-05-02 20:54:17,937 DEBUG logging:103 Processing: 0x1 0x0 0x20 0x0 0x1
2024-05-02 20:54:17,937 DEBUG logging:103 Factory Request[ReadCoilsRequest': 1]
2024-05-02 20:54:17,937 DEBUG logging:103 validate: fc-[1] address-33: count-1
2024-05-02 20:54:17,937 DEBUG logging:103 getValues: fc-[1] address-33: count-1
2024-05-02 20:54:17,937 DEBUG logging:103 send: 0x1 0x1 0x1
2024-05-02 20:54:17,937 DEBUG logging:103 recv: 0x3 0x0 0x4 0x0 0x2 old_data:  addr=None
2024-05-02 20:54:17,937 DEBUG logging:103 Handling data: 0x3 0x0 0x4 0x0 0x2
2024-05-02 20:54:17,937 DEBUG logging:103 Processing: 0x3 0x0 0x4 0x0 0x2
2024-05-02 20:54:17,937 DEBUG logging:103 Factory Request[ReadHoldingRegistersRequest': 3]
2024-05-02 20:54:17,938 DEBUG logging:103 validate: fc-[3] address-5: count-2
2024-05-02 20:54:17,938 DEBUG logging:103 getValues: fc-[3] address-5: count-2
2024-05-02 20:54:17,938 DEBUG logging:103 send: 0x3 0x4 0x0 0x11 0x0 0x11
2024-05-02 20:54:17,938 DEBUG logging:103 -> transport: received eof
2024-05-02 20:54:17,938 DEBUG logging:103 Connection lost server due to None
2024-05-02 20:54:17,938 DEBUG logging:103 Handler for stream [server] has been canceled

Client_async log:

(pymodbus) jan@OldMacMini examples % ./client_async.py --log debug --comm tls
2024-05-02 20:54:17,932 DEBUG logging:103 Connecting to 127.0.0.1:5020.
2024-05-02 20:54:17,932 DEBUG logging:103 Connecting comm
2024-05-02 20:54:17,936 DEBUG logging:103 Connected to comm
2024-05-02 20:54:17,936 DEBUG logging:103 Resetting frame - Current Frame in buffer - 
2024-05-02 20:54:17,936 DEBUG logging:103 Adding transaction 1
2024-05-02 20:54:17,936 DEBUG logging:103 Resetting frame - Current Frame in buffer - 
2024-05-02 20:54:17,936 DEBUG logging:103 send: 0x1 0x0 0x20 0x0 0x1
2024-05-02 20:54:17,937 DEBUG logging:103 recv: 0x1 0x1 0x1 old_data:  addr=None
2024-05-02 20:54:17,937 DEBUG logging:103 Processing: 0x1 0x1 0x1
2024-05-02 20:54:17,937 DEBUG logging:103 Factory Response[ReadCoilsResponse': 1]
2024-05-02 20:54:17,937 DEBUG logging:103 Getting transaction 0
2024-05-02 20:54:17,937 DEBUG logging:103 Adding transaction 2
2024-05-02 20:54:17,937 DEBUG logging:103 Resetting frame - Current Frame in buffer - 
2024-05-02 20:54:17,937 DEBUG logging:103 send: 0x3 0x0 0x4 0x0 0x2
2024-05-02 20:54:17,938 DEBUG logging:103 recv: 0x3 0x4 0x0 0x11 0x0 0x11 old_data:  addr=None
2024-05-02 20:54:17,938 DEBUG logging:103 Processing: 0x3 0x4 0x0 0x11 0x0 0x11
2024-05-02 20:54:17,938 DEBUG logging:103 Factory Response[ReadHoldingRegistersResponse': 3]
2024-05-02 20:54:17,938 DEBUG logging:103 Getting transaction 0
2024-05-02 20:54:17,938 DEBUG logging:103 -> transport: received eof

however there are a problem with the sync client, I will investigate.

./client_sync.py --log debug --comm tls
2024-05-02 20:56:56,101 DEBUG logging:103 Current transaction state - IDLE
2024-05-02 20:56:56,101 DEBUG logging:103 Running transaction 1
2024-05-02 20:56:56,101 DEBUG logging:103 SEND: 0x1 0x0 0x20 0x0 0x1
2024-05-02 20:56:56,102 DEBUG logging:103 New Transaction state "SENDING"
2024-05-02 20:56:56,102 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-05-02 20:56:56,102 DEBUG logging:103 Transaction failed. (The operation did not complete (read) (_ssl.c:2559)) 
2024-05-02 20:56:56,102 DEBUG logging:103 Processing: 
2024-05-02 20:56:56,102 DEBUG logging:103 Getting transaction 1
2024-05-02 20:56:56,102 DEBUG logging:103 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
Traceback (most recent call last):
  File "/Users/jan/repos/pymodbus/examples/./client_sync.py", line 146, in <module>
    main()
  File "/Users/jan/repos/pymodbus/examples/./client_sync.py", line 142, in main
    run_sync_client(testclient, modbus_calls=run_a_few_calls)
  File "/Users/jan/repos/pymodbus/examples/./client_sync.py", line 121, in run_sync_client
    modbus_calls(client)
  File "/Users/jan/repos/pymodbus/examples/./client_sync.py", line 130, in run_a_few_calls
    assert len(rr.bits) == 8
               ^^^^^^^
AttributeError: 'ModbusIOException' object has no attribute 'bits'

Important I cannot produce your "slave does not exist" !

VDigitall commented 1 month ago

In my case, I run an async server and sync client.

AttributeError: 'ModbusIOException' object has no attribute 'bits'

I reproduce it too.

I haven't tried the async server and async client yet.

janiversen commented 1 month ago

But please remember you need to solve the "slave does not exist", independent of the bug in the sync client.

VDigitall commented 1 month ago

Yeah, I rewrote my client using AsyncModbusTlsClient and continue figuring out why I'm receiving slave does not exist. Thanks for your assistance.

janiversen commented 1 month ago

Look at examples/server_async.py + helper.py, that have a correct setup.

VDigitall commented 1 month ago

I figured out why I was receiving slave does not exist. The problem was in misconfiguration. I used framer by default (tls) instead of socket. When I set for tls client and tls server framer socket, I could query all my slaves.

VDigitall commented 1 month ago

But the issue is still reproducible when I'm using an async server and sync client.

Client logs:

python client.py --slave_id 2 --address 1 --count 1
2024-05-02 23:05:29,973 DEBUG logging:103 Current transaction state - IDLE
2024-05-02 23:05:29,973 DEBUG logging:103 Running transaction 1
2024-05-02 23:05:29,973 DEBUG logging:103 SEND: 0x0 0x1 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1 0x0 0x1
2024-05-02 23:05:29,973 DEBUG logging:103 New Transaction state "SENDING"
2024-05-02 23:05:29,974 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-05-02 23:05:29,974 DEBUG logging:103 Transaction failed. (The operation did not complete (read) (_ssl.c:2633)) 
2024-05-02 23:05:29,974 DEBUG logging:103 Processing: 
2024-05-02 23:05:29,974 DEBUG logging:103 Frame check, no more data!
2024-05-02 23:05:29,974 DEBUG logging:103 Getting transaction 1
2024-05-02 23:05:29,974 DEBUG logging:103 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"

Server logs:

2024-05-02 23:08:41,746 DEBUG logging:103 Connected to server
2024-05-02 23:08:41,747 DEBUG logging:103 recv: 0x0 0x1 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1 0x0 0x1 old_data:  addr=None
2024-05-02 23:08:41,747 DEBUG logging:103 Handling data: 0x0 0x1 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1 0x0 0x1
2024-05-02 23:08:41,747 DEBUG logging:103 Processing: 0x0 0x1 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1 0x0 0x1
2024-05-02 23:08:41,747 DEBUG logging:103 Factory Request[ReadHoldingRegistersRequest': 3]
2024-05-02 23:08:41,747 DEBUG logging:103 validate: fc-[3] address-1: count-1
2024-05-02 23:08:41,747 DEBUG logging:103 getValues: fc-[3] address-1: count-1
2024-05-02 23:08:41,747 DEBUG logging:103 send: 0x0 0x1 0x0 0x0 0x0 0x5 0x2 0x3 0x2 0x0 0x0
2024-05-02 23:08:41,747 DEBUG logging:103 Frame check, no more data!
2024-05-02 23:08:41,747 DEBUG logging:103 Connection lost server due to [Errno 54] Connection reset by peer
2024-05-02 23:08:41,747 DEBUG logging:103 Client Disconnection server due to [Errno 54] Connection reset by peer
janiversen commented 1 month ago

As I wrote, that is something I will investigate