When using asyncio, received message is truncated

[marhoy]

Versions

• Python: 3.7.3
• OS: Linux (Debian 10.3 on a rpi3)
• Pymodbus: 2.3.0
• Modbus Hardware: USB <-> serial: FT232 based.

Pymodbus Specific

• Server: A Flexit ventilation aggregate
• Client: rtu - async

Description

I'm trying to use the asyncio serial client with an already running event loop.

Using the sync serial client, I have no problems talking to my modbus device. But the async serial client seems to have several issues. I think my problem is related to #486, #385 which are still unresolved.

Problem 1: run_until_complete() is trying to start an already running loop

Since I'm passing an already running event loop, the loop.run_until_complete() on line 106 of pymodbus/client/asynchronous/factory/serial.py causes a RuntimeError: This event loop is already running (because it is trying to start the loop). It needs to be replaced by instead adding a task to the existing loop:

--- a/pymodbus/client/asynchronous/factory/serial.py
+++ b/pymodbus/client/asynchronous/factory/serial.py
@@ -102,8 +102,7 @@ def async_io_factory(port=None, framer=None, **kwargs):
         sys.exit(1)

     client = AsyncioModbusSerialClient(port, proto_cls, framer, loop, **kwargs)
-    coro = client.connect()
-    loop.run_until_complete(coro)
+    asyncio.ensure_future(client.connect())
     return loop, client

For Python 3.7+, asyncio.create_task() is preferred.

(Another option would be to not run .connect() here, and instead leave that to the user of the client.)

Problem 2: Timing issues with the RTU framer

When using the sync client (works 10/10 times), the communication looks like this:

DEBUG:pymodbus.transaction:Current transaction state - IDLE
DEBUG:pymodbus.transaction:Running transaction 1
DEBUG:pymodbus.transaction:SEND: 0x1 0x4 0xb 0xda 0x0 0x1 0x12 0x15
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x4 0x2 0x0 0x3 0xf9 0x31
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x4 0x2 0x0 0x3
DEBUG:pymodbus.factory:Factory Response[ReadInputRegistersResponse: 4]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.transaction:Getting transaction 1
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
Result: [3]

With the above patch, my asyncio test-script sometimes works, and sometimes doesn't. When it does work, the communication looks like this:

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0xb 0xda 0x0 0x1 0x12 0x15
DEBUG:pymodbus.transaction:Adding transaction 1
INFO:pymodbus.client.asynchronous.asyncio:Connected to /dev/ttyUSB0
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2 0x0 0x3 0xf9 0x31
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x4 0x2 0x0 0x3
DEBUG:pymodbus.factory:Factory Response[ReadInputRegistersResponse: 4]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Getting transaction 1
Result: [3]

When it does not work, it looks like e.g. these three examples, and then the program is just stuck:

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0xb 0xda 0x0 0x1 0x12 0x15
DEBUG:pymodbus.transaction:Adding transaction 1
INFO:pymodbus.client.asynchronous.asyncio:Connected to /dev/ttyUSB0
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2 0x0 0x3 0xf9
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x4 0x2 0x0 0x3 0xf9
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x31
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'1'] not ready

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0xb 0xda 0x0 0x1 0x12 0x15
DEBUG:pymodbus.transaction:Adding transaction 1
INFO:pymodbus.client.asynchronous.asyncio:Connected to /dev/ttyUSB0
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x4 0x2
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x0 0x3 0xf9 0x31
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x0 0x3 0xf9 0x31

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0xb 0xda 0x0 0x1 0x12 0x15
DEBUG:pymodbus.transaction:Adding transaction 1
INFO:pymodbus.client.asynchronous.asyncio:Connected to /dev/ttyUSB0
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2 0x0
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x4 0x2 0x0
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x3 0xf9 0x31
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x3 0xf9 0x31

As you can see, it seems that the received message is truncated: The full message is 7 bytes, but in the three failing examples, the client only receives 6, 3 or 4 bytes before moving on.

I believe this to be an issue with the rtu_framer, but I haven't had time to look into what is causing the problem.

Test-script

This is the script I'm using to test the asyncio client. It is a trimmed-down version of one of the examples in the pymodbus repository.

#!/usr/bin/env python
import logging
import asyncio

from pymodbus.client.asynchronous.serial import AsyncModbusSerialClient as ModbusClient
from pymodbus.client.asynchronous import schedulers

from threading import Thread
import time

logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.DEBUG)


UNIT = 0x01


async def read_from_client(client):
    try:
        log.debug("Read input registers")
        # await client.connect()
        rr = await client.protocol.read_input_registers(3034, 1, unit=UNIT)
        print("Result:", rr.registers)
        client.stop()
    except Exception as e:
        log.exception(e)
        client.transport.close()


def start_loop(loop):
    asyncio.set_event_loop(loop)
    loop.run_forever()


def create_loop():
    loop = asyncio.new_event_loop()
    t = Thread(target=start_loop, args=[loop])
    t.daemon = True
    t.start()
    assert loop.is_running()
    asyncio.set_event_loop(loop)
    return loop


if __name__ == "__main__":

    loop = create_loop()

    loop, client = ModbusClient(
        scheduler=schedulers.ASYNC_IO,
        loop=loop,
        method="rtu",
        port="/dev/ttyUSB0",
        stopbits=1,
        bytesize=8,
        parity="E",
        baudrate=9600,
    )

    future = asyncio.run_coroutine_threadsafe(read_from_client(client), loop=loop)
    while not future.done():
        time.sleep(0.1)
    loop.stop()

[janiversen]

I can confirm this, as I have the same problem. Furthermore async tcp does not allow the use of the RTU framer. When looking at the source code it is not implemented.

[dhoomakethu]

A couple of issues have been fixed with commit e402d9f.

1. Using already running loop

Please give a try with branch https://github.com/riptideio/pymodbus/tree/asyncio-bug-fixes

[raphapassini]

Sorry for commenting in an already closed issue but I do believe it's still broken.
I have 2 scripts doing the same thing, one sync and other async.

Sync Script

import logging
import sys
from time import sleep
from pymodbus.constants import Endian
from pymodbus.client.sync import ModbusSerialClient as ModbusClient
from pymodbus.payload import BinaryPayloadDecoder

from .decoder import ModbusTypeDecoder

logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
logging.getLogger('pymodbus').setLevel(logging.WARNING)
logger = logging.getLogger(__package__)

client = ModbusClient(
    port='/dev/ttyUSB0', stopbits=1, parity='N', bytesize=8,
    baudrate=9600, method="rtu", timeout=3)
client.connect()
logging.info('Conectado')
sleep(3)

memory_types = [
    (408, 2, 'float'),
    (410, 2, 'int32'),
    (418, 1, 'uint16'),
    (420, 1, 'int16'),
    (422, 2, 'int32'),
    (424, 2, 'uint32'),
]

while True:
    for m, c, t in memory_types:
        ds = client.read_holding_registers(m, c, unit=2)
        payload = BinaryPayloadDecoder.fromRegisters(
            ds.registers, Endian.Big, wordorder=Endian.Little)
        decoder = ModbusTypeDecoder()
        parse_func = decoder.parse(t)
        logger.info(f'MEMORIA={m}:{m+c-1} RESULTADO={parse_func(payload)}')
    logger.info('Proxima leitura em 2 segundos...')
    sleep(2)
    break

Async example:

import asyncio
import logging
import sys
from pymodbus.constants import Endian
from pymodbus.client.asynchronous.serial import AsyncModbusSerialClient
from pymodbus.client.asynchronous import schedulers
from pymodbus.payload import BinaryPayloadDecoder

from .decoder import ModbusTypeDecoder

logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
# logging.getLogger('pymodbus').setLevel(logging.WARNING)
logger = logging.getLogger(__package__)

import pdb; pdb.set_trace()
loop, client = AsyncModbusSerialClient(
    schedulers.ASYNC_IO,
    port='/dev/ttyUSB0', stopbits=1, parity='N', bytesize=8,
    baudrate=9600, method="rtu", timeout=10)
client._timeout = 10


async def start_async_test(client):
    logging.info('Conectado')
    await asyncio.sleep(3)

    memory_types = [
        (408, 2, 'float'),
        (410, 2, 'int32'),
        (418, 1, 'uint16'),
        (420, 1, 'int16'),
        (422, 2, 'int32'),
        (424, 2, 'uint32'),
    ]

    while True:
        for m, c, t in memory_types:
            ds = await client.read_holding_registers(m, c, unit=2)
            payload = BinaryPayloadDecoder.fromRegisters(
                ds.registers, Endian.Big, wordorder=Endian.Little)
            decoder = ModbusTypeDecoder()
            parse_func = decoder.parse(t)
            logger.info(f'MEMORIA={m}:{m+c-1} RESULTADO={parse_func(payload)}')
        logger.info('Proxima leitura em 2 segundos...')
        break

if __name__ == "__main__":
    loop.run_until_complete(start_async_test(client.protocol))
    loop.close()

Even after installing the branch mentioned above by @dhoomakethu I still receive the same error about timeout.
Here's the full log for the failing async script posted above.

DEBUG:pymodbus.client.asynchronous.async_io:Connecting.
DEBUG:pymodbus.client.asynchronous.async_io:Client connected to modbus server
INFO:pymodbus.client.asynchronous.async_io:Protocol made connection.
INFO:pymodbus.client.asynchronous.async_io:Connected to /dev/ttyUSB0
INFO:root:Conectado
DEBUG:pymodbus.client.asynchronous.async_io:send: 0x2 0x3 0x1 0x98 0x0 0x2 0x44 0x2b
DEBUG:pymodbus.transaction:Adding transaction 2
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x2
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x02'] not ready
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x3
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x2 0x3
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x4
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x04'] not ready
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x0
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x00'] not ready
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x0
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x00'] not ready
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x0
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x00'] not ready
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x0
DEBUG:pymodbus.framer.rtu_framer:CRC invalid, discarding header!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x4 0x0 0x0 0x0 0x0
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0xc9
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\xc9'] not ready
DEBUG:pymodbus.client.asynchronous.async_io:recv: 0x33
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'3'] not ready
Traceback (most recent call last):
  File "/usr/lib/python3.8/runpy.py", line 192, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/lib/python3.8/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/raphael/stuff/plc-client/plc_client/hw/asimple.py", line 16, in <module>
    loop, client = AsyncModbusSerialClient(
  File "/usr/lib/python3.8/asyncio/base_events.py", line 608, in run_until_complete
    return future.result()
  File "/home/raphael/stuff/plc-client/plc_client/hw/asimple.py", line 38, in start_async_test
    ds = await client.read_holding_registers(m, c, unit=2)
  File "/home/raphael/stuff/plc-client/.venv/lib/python3.8/site-packages/pymodbus/client/asynchronous/async_io/__init__.py", line 35, in execute
    resp = await asyncio.wait_for(req, timeout=self._timeout)
  File "/usr/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

The broken example above is running on top of this branch - git+https://github.com/riptideio/pymodbus.git@asyncio-bug-fixes