asyncio TCP client timeout broken

[aneesahmedpro]

Versions

• Python: 3.8.5
• OS: Ubuntu 20.04.2
• Pymodbus: 2.5.2
• Modbus Hardware (if used): No hardware used

Pymodbus Specific

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

Description

What were you trying?

A very simplistic TCP-only setup.

1. Install pymodbus default (minimal) package: pip install pymodbus
2. Create a TCP server which has a datastore which takes 5 seconds to process a register-write.
3. Create an asyncio based TCP client which requests a register-write into the datastore and has timeout of 10 seconds.

To do this, created client like this:

from pymodbus.client.asynchronous.tcp import AsyncModbusTCPClient as ModbusTcpClient
loop, client = ModbusTcpClient(schedulers.ASYNC_IO, port=5020, timeout=10)

Full server and client code can be found near the end of this report.

What did you expect?

That client waits for server to process the register-write, without raising TimeoutError exception.

What went wrong?

Client raised TimeoutError exception. Log can be found near the end of this report.

Observations

I snooped around the library code a bit, and stumbled upon BaseAsyncModbusClient class. It has self._timeout member, which gets default initialised to 2 seconds.

So I tried this instead:

from pymodbus.client.asynchronous.tcp import AsyncModbusTCPClient as ModbusTcpClient
loop, client = ModbusTcpClient(schedulers.ASYNC_IO, port=5020)
client.protocol._timeout = 10

And it works! It correctly waits long enough for the server to reply. So, I think somewhere in the library, the chain of timeout passing down to the base class has a breakage somewhere. I'm not sure though.

Code and Logs

This is the server code. It is sync variant, but that is an irrelevant detail. This could be any sync/async variant.

# server.py

import time
from pymodbus.server.sync import StartTcpServer
from pymodbus.datastore import ModbusSequentialDataBlock
from pymodbus.datastore import ModbusSlaveContext, ModbusServerContext

import logging
logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.INFO)


class CustomDataBlock(ModbusSequentialDataBlock):

    def setValues(self, address, values):

        log.info('[begin] set values')

        super().setValues(address, values)

        time.sleep(5)

        log.info('[end] set values')


def main():

    store = ModbusSlaveContext(
        di=None,
        co=None,
        hr=CustomDataBlock(1, [123]*100),
        ir=None,
        zero_mode=True,
    )
    context = ModbusServerContext(slaves=store, single=True)

    StartTcpServer(context, address=('localhost', 5020))


if __name__ == '__main__':

    main()

This is the client code.

# client.py

from pymodbus.client.asynchronous.tcp import AsyncModbusTCPClient as ModbusTcpClient
from pymodbus.client.asynchronous import schedulers

import logging
logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.INFO)


async def run(client):

    log.info("[test] Write to multiple holding registers and read back")
    rq = await client.write_registers(1, [456]*10)
    rr = await client.read_holding_registers(1, 10)
    assert(rq.function_code < 0x80)     # test that we are not an error
    assert(rr.registers == [456]*10)    # test the expected value
    log.info("[success] Write to multiple holding registers and read back")


def main():

    #### [begin] this demonstrates bug
    loop, client = ModbusTcpClient(schedulers.ASYNC_IO, port=5020, timeout=10)
    #### [end]

    #### [begin] this is a (dirty) workaround for the bug
    # loop, client = ModbusTcpClient(schedulers.ASYNC_IO, port=5020)
    # client.protocol._timeout = 10
    #### [end]

    loop.run_until_complete(run(client.protocol))
    loop.close()


if __name__ == '__main__':

    main()

This is the output of the client code (for the case where bug is demonstrated).

INFO:pymodbus.client.asynchronous.async_io:Protocol made connection.
INFO:pymodbus.client.asynchronous.async_io:Connected to 127.0.0.1:5020.
INFO:root:[test] Write to multiple holding registers and read back
Traceback (most recent call last):
  File "client.py", line 30, in <module>
    main()
  File "client.py", line 24, in main
    loop.run_until_complete(run(client.protocol))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "client.py", line 13, in run
    rq = await client.write_registers(1, [456]*10)
  File "/tmp/project/.venv/lib/python3.8/site-packages/pymodbus-2.5.2-py3.8.egg/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
  File "/usr/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

[aneesahmedpro]

Could this be the root cause? Look at the async_io_factory function in client/asynchronous/factory/tcp.py

def async_io_factory(host="127.0.0.1", port=Defaults.Port, framer=None,
                     source_address=None, timeout=None, **kwargs):
    """
    Factory to create asyncio based asynchronous tcp clients
    :param host: Host IP address
    :param port: Port
    :param framer: Modbus Framer
    :param source_address: Bind address
    :param timeout: Timeout in seconds
    :param kwargs:
    :return: asyncio event loop and tcp client
    """

This function does not end up using the timeout argument it accepts.