Multiple Asynchronous Calls to read_holding_register Result in a Timeout

[aryker]

Versions

• Python: 3.9
• OS: Ubuntu 18.04, Docker
• Pymodbus: 3.5.0
• Modbus Hardware (if used): Votek UT-1128-EN

Pymodbus Specific

• Server: N/A
• Client: rtu - async

Description

I have three slave devices connected to my modbus hub, and I am trying to read a holding register from each one. When I make more than one asynchronous call to read_holding_registers in quick succession, pymodbus reports a ModbusIOException stating that no response was received after 3 retries. This does not happen when I only call the read method once, or if I wait long enough between asynchronous calls. It also does not happen with synchronous calls. My USB-Serial modem has a TX/RX light that flashes green whenever data is traveling to/from the modbus device. Using this, I can confirm that in the erroneous situation, pymodbus is not sending data over the line at all (the light does not come on).

Code and Logs

from pymodbus.client import AsyncModbusSerialClient
from pymodbus import pymodbus_apply_logging_config
import asyncio

pymodbus_apply_logging_config("DEBUG")

client = AsyncModbusSerialClient(
    strict=False,
    method='rtu',
    port='/dev/ttyUSB0',
    baudrate=19200,
    timeout=0.5,
    parity='N',
    stopbits=2,
    bytesize=8
)

async def test_connect():
    await client.connect()

async def test_read(slave):
    while True:
        if client.connected:
            await asyncio.sleep(1.0)
            res = await client.read_holding_registers(address=1, count=1, slave=slave)
            print(res.registers)
            return
        else:
            await asyncio.sleep(0.1)

def main():
    tasks = []
    tasks.append(test_connect())
    tasks.append(test_read(101))
    tasks.append(test_read(102)) # Comment this line and the line below out for working code.
    tasks.append(test_read(105)) # Comment this line and the line above out for working code.
    loop = asyncio.get_event_loop()
    loop.run_until_complete(asyncio.gather(*tasks))

main()

2023-09-20 11:42:27,024 DEBUG logging:102 Connecting to /dev/ttyUSB0.
2023-09-20 11:42:27,024 DEBUG logging:102 Connecting comm
2023-09-20 11:42:27,028 DEBUG logging:102 Connected to comm
2023-09-20 11:42:27,028 DEBUG logging:102 callback_connected called
2023-09-20 11:42:28,128 DEBUG logging:102 send: 0x65 0x3 0x0 0x1 0x0 0x1 0xdd 0xee
2023-09-20 11:42:28,129 DEBUG logging:102 Adding transaction 101
2023-09-20 11:42:28,130 DEBUG logging:102 send: 0x66 0x3 0x0 0x1 0x0 0x1 0xdd 0xdd
2023-09-20 11:42:28,130 DEBUG logging:102 Adding transaction 102
2023-09-20 11:42:28,131 DEBUG logging:102 send: 0x69 0x3 0x0 0x1 0x0 0x1 0xdd 0x22
2023-09-20 11:42:28,131 DEBUG logging:102 Adding transaction 105
2023-09-20 11:42:28,632 DEBUG logging:102 send: 0x65 0x3 0x0 0x1 0x0 0x1 0xdd 0xee
2023-09-20 11:42:28,633 DEBUG logging:102 Adding transaction 101
2023-09-20 11:42:28,634 DEBUG logging:102 send: 0x66 0x3 0x0 0x1 0x0 0x1 0xdd 0xdd
2023-09-20 11:42:28,634 DEBUG logging:102 Adding transaction 102
2023-09-20 11:42:28,635 DEBUG logging:102 send: 0x69 0x3 0x0 0x1 0x0 0x1 0xdd 0x22
2023-09-20 11:42:28,636 DEBUG logging:102 Adding transaction 105
2023-09-20 11:42:29,136 DEBUG logging:102 send: 0x65 0x3 0x0 0x1 0x0 0x1 0xdd 0xee
2023-09-20 11:42:29,137 DEBUG logging:102 Adding transaction 101
2023-09-20 11:42:29,137 DEBUG logging:102 send: 0x66 0x3 0x0 0x1 0x0 0x1 0xdd 0xdd
2023-09-20 11:42:29,138 DEBUG logging:102 Adding transaction 102
2023-09-20 11:42:29,139 DEBUG logging:102 send: 0x69 0x3 0x0 0x1 0x0 0x1 0xdd 0x22
2023-09-20 11:42:29,140 DEBUG logging:102 Adding transaction 105
2023-09-20 11:42:29,639 DEBUG logging:102 send: 0x65 0x3 0x0 0x1 0x0 0x1 0xdd 0xee
2023-09-20 11:42:29,640 DEBUG logging:102 Adding transaction 101
2023-09-20 11:42:29,641 DEBUG logging:102 send: 0x66 0x3 0x0 0x1 0x0 0x1 0xdd 0xdd
2023-09-20 11:42:29,641 DEBUG logging:102 Adding transaction 102
2023-09-20 11:42:29,642 DEBUG logging:102 send: 0x69 0x3 0x0 0x1 0x0 0x1 0xdd 0x22
2023-09-20 11:42:29,643 DEBUG logging:102 Adding transaction 105
2023-09-20 11:42:30,143 DEBUG logging:102 Connection lost comm due to Server not responding
2023-09-20 11:42:30,144 DEBUG logging:102 Getting transaction 101
2023-09-20 11:42:30,144 DEBUG logging:102 Getting transaction 102
2023-09-20 11:42:30,144 DEBUG logging:102 Getting transaction 105
2023-09-20 11:42:30,148 DEBUG logging:102 Wait comm 100.0 ms before reconnecting.
Traceback (most recent call last):
  File "/home/acr/./test.py", line 40, in <module>
    main()
  File "/home/acr/./test.py", line 38, in main
    loop.run_until_complete(asyncio.gather(*tasks))
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 647, in run_until_complete
    return future.result()
  File "/home/acr/./test.py", line 25, in test_read
    res = await client.read_holding_registers(address=1, count=1, slave=slave)
  File "/home/acr/.local/lib/python3.9/site-packages/pymodbus/client/base.py", line 210, in async_execute
    raise ModbusIOException(
pymodbus.exceptions.ModbusIOException: Modbus Error: [Input/Output] ERROR: No response received after 3 retries

[janiversen]

First of all you use a serial line, so alone for that reason you cannot run multiple requests in parallel, I am not sure how you expect that to work ?

Pymodbus in general do not support parallel requests, because the modbus protocol is a request/response protocol, and even though tcp in principle allows multiple requests, most devices do not accept it.

If you execute the requests sequentially there are no need for delay between the requests.

[aryker]

I'm not sure I understand your point. My understanding of Python's asynchronous event loop is that it is not truly parallel. If asynchronous calls like this are not possible with a serial device then why does an asynchronous version of the serial client exist? What am I missing conceptually here?

[janiversen]

You must ensure that your pymodbus calls are serialised. You cannot have 2 calls open at any time.

Async means you can do a lot of other things while the call is executing, except calling a pymodbus function.

[aryker]

Alright, that is helpful, thank you.

If I am using the asynchronous pymodbus clients, is there a way to tell before calling a pymodbus function whether another one is currently running and it is thus unsafe to do so? In my actual application I am doing other things between pymodbus calls, but it seems like there are cases where I am not doing "enough" and I would need to wait before making another call.

[janiversen]

no, that is responsibility of the app. You could isolate the pymodbus call in a method in your app and secure it with a lock.

[kishorevenki]

Hi, I also noticed that in Pymodbus version 3.5.2 (pyserial version 3.5) pymodbus does not read the packets that are correctly received from the server, even though the poll message was sent only once and that too using sync-client. Pymodbus always throw ModbusIOException. Hence I thought of updating here rather than opening a new thread. I am testing in Ubuntu 22.04 with python 3.10 in venv using /dev/ttyUSB0.

While debugging I also noticed that the slave responded immediately but pymodbus is waiting for 6 sec to wait for the packets whereas the packets are already received. I am mentioning 6 sec based on the debug messages which are placed below. ---Reading Holding Registers - 03--- 2023-10-01 21:55:49,848 MainThread INFO LGMeter_Interface:62 ### Creating a modbus client with LG6435_Meter PLC ### 2023-10-01 21:55:49,850 MainThread INFO LGMeter_Interface:195 ### Opening the connection with LG6435_Meter PLC### 2023-10-01 21:55:49,851 MainThread DEBUG logging :102 Current transaction state - IDLE 2023-10-01 21:55:49,851 MainThread DEBUG logging :102 Running transaction 1 2023-10-01 21:55:49,851 MainThread DEBUG logging :102 SEND: 0xed 0x3 0x0 0x8e 0x0 0x2 0xb2 0x8c 2023-10-01 21:55:49,852 MainThread DEBUG logging :102 New Transaction state "SENDING" 2023-10-01 21:55:49,852 MainThread DEBUG logging :102 Changing transaction state from "SENDING" to "WAITING FOR REPLY" 2023-10-01 21:55:55,868 MainThread DEBUG logging :102 No response received, Expected 9 bytes Received 0 bytes !!!! 2023-10-01 21:55:55,868 MainThread DEBUG logging :102 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" 2023-10-01 21:55:55,869 MainThread DEBUG logging :102 RECV: 2023-10-01 21:55:55,869 MainThread DEBUG logging :102 Processing: 2023-10-01 21:55:55,869 MainThread DEBUG logging :102 Getting transaction 237 2023-10-01 21:55:55,869 MainThread DEBUG logging :102 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" 2023-10-01 21:55:55,869 MainThread INFO LGMeter_Interface:205 ### Client is closed### Traceback (most recent call last): AttributeError: 'ModbusIOException' object has no attribute 'registers'

At 2023-10-01 21:55:49,852, the state is SENDING and the packets were sent and response also immediately received. At 2023-10-01 21:55:55,868, waiting for the bytes. The issue is same when client.strict is set to FALSE as well & retry_on_empty is set to TRUE as well.

[janiversen]

Your problem is here:

2023-10-01 21:55:55,868 MainThread DEBUG logging :102 No response received, Expected 9 bytes Received 0 bytes !!!!

your device do not respond so pymodbus makes a retry.

[kishorevenki]

But I have printed out the response from the slave device using serial monitor. Hence at the beginning of my thread, I have clearified that for every poll, indeed the slave had responded but pymodbus is failing to receive it as it is waiting for the timeout. I have installed modpoll the commandline tool in ubuntu and verified that the slave device indeed responded.

[janiversen]

Modpoll might have another timeout than what you defined for pymodbus, fact is that pymodbus do not get a response and thus reconnects.

[janiversen]

The problem can be in your usb device, many times using a larger timeout solved the problem,

[kishorevenki]

Hi, I am trying to confirmly saying here that the slave device indeed responded right after the polling message is sent and no need for pymodbus client to wait for the timeout. Since the response is less than a sec, why the requirement for greater timeout arise. I have printed using serial monitor to print the response in the termainal. I could notice that right after the response was sent, response was received in the USB device.

While the slave device is sending response, pymodbus is waiting for the delay for 6 sec. Waiting for 6 sec is constant irrespective of the timeout value and number of retries.

Would like to confirm there is response from the slave device for each query sent from pymodbus.

[janiversen]

You might see it on the serial monitor, but as you can see from the log message pymodbus do not receive it !

This can be caused by a lot of things outside the control of pymodbus:

• your usb device buffers the data
• the os buffers the data
• your device responds with another slave id (did you check what is on the serial line).

[janiversen]

Pymodbus is NOT waiting 6 seconds if it receives a response, but 6 seconds sounds a lot like the first retry.

If you want to convince yourself that the throughput is higher than 1 message pr 6 seconds, try our performance example.

[janiversen]

And just to be clear timeout > 6 do affect the response time in your case, because pymodbus waits longer to receive a response.

[janiversen]

Just had another look at your code, you must guarantee that the calls are sequential (one call terminates before issuing the next). That is due to the nature of the modbus protocol.

Your problem is likely because your app tries to make multiple reads in parallel.

[kishorevenki]

You might see it on the serial monitor, but as you can see from the log message pymodbus do not receive it !

This can be caused by a lot of things outside the control of pymodbus:

• your usb device buffers the data
• the os buffers the data
• your device responds with another slave id (did you check what is on the serial line).

I have only one device connected to it. So in the RS485 network of 38.4K baud, one pymodbus and the slave device. if my USB device buffers the data, how the response is printed in serial monitor. Secondly how come other modbus client in the same m/c (of course pymodbus is OFF when other client is made active), gets the response. Somehow I am not technically convinced.

[janiversen]

You cannot have multiple calls in parallel that is not supported neither by pymodbus nor by the modbus protocol.

Pull requests are welcome if you want that to be supported, but bear in mind that on the RS485 you can only have 1 request outstanding (request/response protocol).

[kishorevenki]

Just had another look at your code, you must guarantee that the calls are sequential (one call terminates before issuing the next). That is due to the nature of the modbus protocol.

Your problem is likely because your app tries to make multiple reads in parallel.

This is not the same message as you see in the first thread raised by aryker. So I am not sending multiple message parallel. Since I am facing the similar issue I used this thread instead of creating a new. Pls refer my first comment.

[janiversen]

This code '''

def main(): tasks = [] tasks.append(test_connect()) tasks.append(test_read(101)) tasks.append(test_read(102)) # Comment this line and the line below out for working code. tasks.append(test_read(105)) # Comment this line and the line above out for working code. loop = asyncio.get_event_loop() loop.run_until_complete(asyncio.gather(*tasks)) '''

Can make multiple calls in parallel, actually you do not even ensure that connect() terminates before starting to read.

[janiversen]

If your code is different then why piggy back on this issue, it is not very helpful for anybody.

[kishorevenki]

Hi Janiversen, If you want, I will create new thread. But the problem statement is PYSERIAL is not recognizing the packets that are received foor the function code 6 (READ_HIOLDING_REG) For me the topic lookes same. and hence I coninued here. Sorry for that...

[kishorevenki]

If you intend to open an new issue and discuss there, I am ready to do the same. Pls suggest.

[janiversen]

Well it is quite different, since you do not have multiple calls in parallel.

You need to make a proper issue with log, code etc....I am not even sure if you use async or sync.

BUT the response, based on your log, is still the same, pymodbus do not receive the response! it might be that PYSERIAL have a problem but that is another project!

And please do you really think that pymodbus would be useable if every request took 6 seconds to respond to ? Pymodbus can serve around 40-50 request pr second.

[kishorevenki]

Hi, Sorry for the confusion. If you suggest to move to new thread, I am OK.

• I use sync_client.

• I am concerned why pymodbus to wait for 6 sec. Please suggest me to where to change this wait time, I can try and give you feedback.