A lot of timeouts with async tcp client

[rzulian]

Versions

• Python: 3.10
• OS: macOS
• Pymodbus: dev
• Modbus Hardware (if used): SOlaredge Inverter

Pymodbus Specific

• Client: tcp - async

Description

What were you trying, what has happened, what went wrong, and what did you expect? I'm getting a lot of errors while trying to connect to the Solaredge Inverter. This wasn't happening sometime ago, so I'm not sure what is changed. I'm assuming that the Inverter has the same firmware. I've changed the network to a Unifi UDM pro + switches. How can I understand what's wrong?

Code and Logs

 # code and logs here.

20:52:19 WARNING __init__:34 Importing deprecated clients. Dependency Twisted is Installed
20:52:19 DEBUG async_asyncio_client_solaredge:145 Running Async client
20:52:19 DEBUG async_asyncio_client_solaredge:146 ------------------------------------------------------
20:52:19 DEBUG async_asyncio_client_solaredge:79 Running Async client with asyncio loop not yet started
20:52:19 DEBUG async_asyncio_client_solaredge:80 ------------------------------------------------------
20:52:19 DEBUG selector_events:54 Using selector: KqueueSelector
/Users/riccardo/Workspace/pymodbus/pymodbus/client/asynchronous/factory/tcp.py:83: DeprecationWarning: There is no current event loop
  client = loop.run_until_complete(asyncio.gather(cor))[0]
20:52:19 DEBUG __init__:262 Connecting to 192.168.1.6:502.
20:52:19 DEBUG __init__:283 Connecting.
20:52:19 DEBUG __init__:104 Client connected to modbus server
20:52:19 INFO  __init__:300 Protocol made connection.
20:52:19 DEBUG async_asyncio_client_solaredge:51 Reading Holding Registers
20:52:19 DEBUG async_asyncio_client_solaredge:55 Reading Holding Registers Inverter 1
20:52:19 DEBUG __init__:135 send: 0x0 0x1 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x4
20:52:19 DEBUG transaction:507 Adding transaction 1
20:52:24 ERROR async_asyncio_client_solaredge:71 exception: 
Traceback (most recent call last):
  File "/Users/riccardo/opt/anaconda3/envs/test/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/riccardo/Workspace/pymodbus/examples/common/async_asyncio_client_solaredge.py", line 56, in start_async_test
    rr = await client.read_holding_registers(40000, 4, unit=UNIT, timeout=1)
  File "/Users/riccardo/Workspace/pymodbus/pymodbus/client/asynchronous/async_io/__init__.py", line 42, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/Users/riccardo/opt/anaconda3/envs/test/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

20:52:26 DEBUG async_asyncio_client_solaredge:55 Reading Holding Registers Inverter 1
20:52:26 DEBUG __init__:135 send: 0x0 0x2 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x4
20:52:26 DEBUG transaction:507 Adding transaction 2
20:52:31 ERROR async_asyncio_client_solaredge:71 exception: 
Traceback (most recent call last):
  File "/Users/riccardo/opt/anaconda3/envs/test/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/riccardo/Workspace/pymodbus/examples/common/async_asyncio_client_solaredge.py", line 56, in start_async_test
    rr = await client.read_holding_registers(40000, 4, unit=UNIT, timeout=1)
  File "/Users/riccardo/Workspace/pymodbus/pymodbus/client/asynchronous/async_io/__init__.py", line 42, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/Users/riccardo/opt/anaconda3/envs/test/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

20:52:33 DEBUG async_asyncio_client_solaredge:55 Reading Holding Registers Inverter 1
20:52:33 DEBUG __init__:135 send: 0x0 0x3 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x4
20:52:33 DEBUG transaction:507 Adding transaction 3
20:52:38 ERROR async_asyncio_client_solaredge:71 exception: 
Traceback (most recent call last):
  File "/Users/riccardo/opt/anaconda3/envs/test/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/riccardo/Workspace/pymodbus/examples/common/async_asyncio_client_solaredge.py", line 56, in start_async_test
    rr = await client.read_holding_registers(40000, 4, unit=UNIT, timeout=1)
  File "/Users/riccardo/Workspace/pymodbus/pymodbus/client/asynchronous/async_io/__init__.py", line 42, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/Users/riccardo/opt/anaconda3/envs/test/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

20:52:39 DEBUG __init__:145 recv: 0x0 0x1 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41
20:52:39 DEBUG socket_framer:167 Processing: 0x0 0x1 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41
20:52:39 DEBUG factory:351 Factory Response[ReadHoldingRegistersResponse': 3]
20:52:39 DEBUG transaction:519 Getting transaction 1
20:52:39 DEBUG __init__:145 recv: 0x0 0x2 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41
20:52:39 DEBUG socket_framer:167 Processing: 0x0 0x2 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41
20:52:39 DEBUG factory:351 Factory Response[ReadHoldingRegistersResponse': 3]
20:52:39 DEBUG transaction:519 Getting transaction 2
20:52:39 DEBUG __init__:145 recv: 0x0 0x3 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41
20:52:39 DEBUG socket_framer:167 Processing: 0x0 0x3 0x0 0x0 0x0 0xb 0x1 0x3 0x8 0x53 0x75 0x6e 0x53 0x0 0x1 0x0 0x41
20:52:39 DEBUG factory:351 Factory Response[ReadHoldingRegistersResponse': 3]
20:52:39 DEBUG transaction:519 Getting transaction 3
20:52:40 DEBUG async_asyncio_client_solaredge:55 Reading Holding Registers Inverter 1
20:52:40 DEBUG __init__:135 send: 0x0 0x4 0x0 0x0 0x0 0x6 0x1 0x3 0x9c 0x40 0x0 0x4

[janiversen]

Seems you have a slow network or some routing problems. Are the client and the solarEdge on the same network physically as well as in address ?

You can also define timeout when creating the client.

[rzulian]

The client and the Solaredge inverters are in the same vlan. I've also tried to move them to the same switch. The timeout in this example is set to 5 secs. But even a larger timeout doesn't solve the problem in my tests.

    loop = asyncio.new_event_loop()
    assert not loop.is_running()  # nosec
    asyncio.set_event_loop(loop)
    new_loop, client = ModbusClient(  # pylint: disable=unpacking-non-sequence
        schedulers.ASYNC_IO,  host="192.168.1.6",port=502, loop=loop, timeout=5
    )
    loop.run_until_complete(start_async_test(client.protocol))
    loop.close()

[janiversen]

The same vlan does not mean the are in the same logical network, does your client have a 192.168.1.? address, otherwise you should look at potential routing problems.

You have something that adds packet delays, this is not uncommon with a vlan. Putting both on a switch would eliminate that potential problem.

I am not saying that this is not a bug, just that there are a couple of things which needs to be ruled out.

[github-actions[bot]]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

[janiversen]

Did you solve your problem ?

[github-actions[bot]]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.