Serial asyncio client does not recover after device goes online

[wrobell]

Versions

• Python: 3.7.2
• OS: Linux
• Pymodbus: 2.2.0rc1
• Modbus Hardware (if used): Growatt 1500-s

Pymodbus Specific

• Client: rtu - async

Description

The Growatt 1500-s is a solar panel inverter. I am connecting to it via USB to serial cable.

When there is not enough energy from the solar panels, the inverter shuts down. The serial device still exists, you can send data, but you cannot receive anything. Once the inverter gets online, I would expect to receive the data, but pymodbus seems to hang.

I am trying to read data in the following manner

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

[...]

 _, client = ModbusClient(
    schedulers.ASYNC_IO,
    method='rtu',
    port='/dev/ttyUSB)',
    baudrate=9600,
    stopbits=1,
    parity='N',
    bytesize=8,
)

async def read():   # note: run in a loop
    rr = await client.protocol.read_input_registers(register, 1, unit=unit)
    return transform(rr.registers[0])

This works when the inverter is online. When the inverter goes offline, the await statements hangs. Unfortunately it never recovers. I would expect it to work again once the inverter goes online again.

I have also tried to change the read coroutine into

async def read():  # note: run in a loop
    try:         
        task = client.protocol.read_input_registers(register, 1, unit=unit)
        rr = await asyncio.wait_for(task, timeout=1)
        return transform(rr.registers[0])                        
    except asyncio.TimeoutError as ex:
        task.cancel()

This did not help either.

Below are the debug logs from pymodbus for the 2nd version of read. As you can see, at some stage the inverter starts responding, pymodbus is receiving data, but unfortunately the client.protocol.read_inout_registers does not return any data

DEBUG:pymodbus.client.asynchronous.asyncio:Connecting.
DEBUG:pymodbus.client.asynchronous.asyncio:Client connected to modbus server
INFO:pymodbus.client.asynchronous.asyncio:Protocol made connection.
INFO:pymodbus.client.asynchronous.asyncio:Connected to /dev/ttyUSB0

[... while the inverter is offline, connection is successful... ]

DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x0
DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x00'] not ready
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x2 0x0 0x1 0x90 0xa
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1d 0x0 0x1 0xa1 0xcc
DEBUG:pymodbus.transaction:Adding transaction 2
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1b 0x0 0x1 0x41 0xcd
DEBUG:pymodbus.transaction:Adding transaction 3

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1b 0x0 0x1 0x41 0xcd
DEBUG:pymodbus.transaction:Adding transaction 4
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1d 0x0 0x1 0xa1 0xcc
DEBUG:pymodbus.transaction:Adding transaction 5
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x2 0x0 0x1 0x90 0xa
DEBUG:pymodbus.transaction:Adding transaction 6
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x0

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1d 0x0 0x1 0xa1 0xcc
DEBUG:pymodbus.transaction:Adding transaction 7
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x2 0x0 0x1 0x90 0xa
DEBUG:pymodbus.transaction:Adding transaction 8
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1b 0x0 0x1 0x41 0xcd
DEBUG:pymodbus.transaction:Adding transaction 9
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x0

[... the inverter is about to get online ... ]

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1d 0x0 0x1 0xa1 0xcc
DEBUG:pymodbus.transaction:Adding transaction 1918
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x2 0x0 0x1 0x90 0xa
DEBUG:pymodbus.transaction:Adding transaction 1919
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1b 0x0 0x1 0x41 0xcd
DEBUG:pymodbus.transaction:Adding transaction 1920
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1d 0x0 0x1 0xa1 0xcc
DEBUG:pymodbus.transaction:Adding transaction 1921
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x1b 0x0 0x1 0x41 0xcd
DEBUG:pymodbus.transaction:Adding transaction 1922
DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x2 0x0 0x1 0x90 0xa
DEBUG:pymodbus.transaction:Adding transaction 1923
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2 0x31 0x53 0xec 0x9d
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2 0x0 0x0 0xb9 0x30
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x2 0x0 0x0 0xb9
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x30

[dhoomakethu]

Could be similar to #349

[wrobell]

The issue can be simulated with the scripts p1.py and p2.py (see the code below).

To reproduce the problem

1. Create virtual serial device with socat

$ socat -d -d PTY,link=/tmp/ptyp0,raw,echo=0,ispeed=9600 PTY,link=/tmp/ttyp0,raw,echo=0,ospeed=9600

2. Run p1.py script.
3. Run p2.py script with ok parameter.
4. The p1.py script will print received 12627.
5. Now run p2.py script with fail parameter.
6. The pymodbus in p1.py script will log DEBUG:pymodbus.framer.rtu_framer:Frame - [b'\x00'] not ready. This is fine.
7. Try to run the p2.py script with ok parameter again.
8. At this stage p1.py will never print received 12627. This is despite pymodbus logging that it received the data.

The p1.py script

import logging
from pymodbus.client.asynchronous.serial import (
    AsyncModbusSerialClient as ModbusClient)
from pymodbus.client.asynchronous import schedulers

logging.basicConfig(level=logging.DEBUG)

async def read(client):
    while True:
        rr = await client.read_input_registers(2, 1, unit=1)
        print('received', rr.registers[0])


# socat -d -d PTY,link=/tmp/ptyp0,raw,echo=0,ispeed=9600 PTY, link=/tmp/ttyp0,raw,echo=0,ospeed=9600
loop, client = ModbusClient(
    schedulers.ASYNC_IO,
    port='/tmp/ptyp0',
    baudrate=9600,
    method='rtu'
)
loop.run_until_complete(read(client.protocol))
loop.close()

The p2.py script

import serial
import sys

assert sys.argv[1] in ('fail', 'ok')
fail = sys.argv[1] == 'fail'

dev = serial.Serial('/tmp/ttyp0', baudrate=9600, bytesize=8, parity='N', stopbits=1)
if fail:
    dev.write([0x0])
else:
    dev.write([0x1, 0x4, 0x2, 0x31, 0x53, 0xec, 0x9d])

[dhoomakethu]

I was able to reproduce this with your provided code and was able to work around it using async_timeout and pymodbus 2.2.0rc2.

import logging
import asyncio
from async_timeout import timeout
from pymodbus.client.asynchronous.serial import (
    AsyncModbusSerialClient as ModbusClient)
from pymodbus.client.asynchronous import schedulers
FORMAT = ('%(asctime)-15s %(threadName)-15s '
          '%(levelname)-8s %(module)-15s:%(lineno)-8s %(message)s')
logging.basicConfig(level=logging.DEBUG, format=FORMAT)

async def read(client):
    while True:
        try:
            async with timeout(2):
                rr = await client.read_input_registers(2, 1, unit=1)
                logging.debug('received - {}'.format(rr.registers[0]))
        except asyncio.TimeoutError:
            logging.debug('Timeout!!')
            # client.close()


# socat -d -d PTY,link=/tmp/ptyp0,raw,echo=0,ispeed=9600 PTY, link=/tmp/ttyp0,raw,echo=0,ospeed=9600
loop, client = ModbusClient(
    schedulers.ASYNC_IO,
    port='/tmp/ptyp0',
    baudrate=9600,
    method='rtu'
)
loop.run_until_complete(read(client.protocol))
loop.close()

[wrobell]

thanks, it will take me 2 days to test it or so.

[wrobell]

There is still an issue with long running tasks.

This can be simulated with the following

1. Run with p1.py script with

    while True:
        task = client.read_input_registers(2, 28, unit=1)
        try:
            rr = await asyncio.wait_for(task, timeout=1)
            print('\nDONE', rr, '\n')
        except asyncio.TimeoutError as ex:
            print('TIMEOUT')
            task.cancel()
        await asyncio.sleep(1)

2. Run script p2.py after 15 seconds.
3. pymodbus reports that data is received, but rr = await... timeout=1) still timeouts.
4. After a period of time, the data is returned by new tasks.

It seems, that despite task cancellation, pymodbus still tries to return the data via timed-out tasks. I assume transactions are accumulated.

In my case, inverter is offline for 15+ hours at the moment, which will probably accumulate 54000+ transactions, so I will never receive any data.

[wrobell]

Is there any other additional data to be provided to push this issue forward?

[dhoomakethu]

@wrobell sorry, I got offtrack with other activities. I will try to see if I can work on this over the weekend or in up coming weeks .

[pazzarpj]

Can you try this with 2.2.0
#367 was merged into it and I think might help

[wrobell]

I am in the process of testing.

I would like to note that with newer versions of socat, the speed needs to be prefixed with b, i.e.

socat -d -d PTY,link=/tmp/ptyp0,raw,echo=0,ispeed=b9600 PTY,link=/tmp/ttyp0,raw,echo=0,ospeed=b9600

[wrobell]

The initial testing with the scripts above looks promising. Testing now with the real device.

[wrobell]

Unfortunately, there is still something wrong with the asyncio data read:

DEBUG:pymodbus.client.asynchronous.asyncio:send: 0x1 0x4 0x0 0x2 0x0 0x1c 0x50 0x3
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x1 0x4 0x38 0x6 0x60
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x4 0x38 0x6 0x60
DEBUG:pymodbus.client.asynchronous.asyncio:recv: 0x6 0xc7 0x0 0x9 0x0 0x0 0x6 0x60 0x0 0x0 0x0 0x0 0x0 0x0
DEBUG:pymodbus.framer.rtu_framer:CRC invalid, discarding header!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x6 0xc7 0x0 0x9 0x0 0x0 0x6 0x60 0x0 0x0 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.asyncio:recv: 0x0 0x0 0x0 0x0 0x5 0xbd 0x13 0x86 0x9 0x1 0x0 0x6 0x0 0x0 0x5 0xbd 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2 0x0 0x0 0x41 0x8b 0x6f 0xcc
DEBUG:pymodbus.framer.rtu_framer:CRC invalid, discarding header!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x0 0x0 0x0 0x0 0x5 0xbd 0x13 0x86 0x9 0x1 0x0 0x6 0x0 0x0 0x5 0xbd 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2 0x0 0x0 0x41 0x8b 0x6f 0xcc
DEBUG:pymodbus.framer.rtu_framer:Frame check failed, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer -

If I switch to standard serial client:

DEBUG:pymodbus.transaction:Running transaction 57
DEBUG:pymodbus.transaction:SEND: 0x1 0x4 0x0 0x2 0x0 0x1c 0x50 0x3
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1557644102.205096, Current Time stamp - 1557644103.043654
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 0x38 0x6 0x12 0x7 0xe 0x0 0x8 0x0 0x0 0x6 0x12 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x5 0x77 0x13 0x86 0x9 0x1 0x0 0x6 0x0 0x0 0x5 0x77 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2 0x0 0x0 0x41 0x8b 0x49 0x49
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x4 0x38 0x6 0x12 0x7 0xe 0x0 0x8 0x0 0x0 0x6 0x12 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x5 0x77 0x13 0x86 0x9 0x1 0x0 0x6 0x0 0x0 0x5 0x77 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2 0x0 0x0 0x41 0x8b
DEBUG:pymodbus.factory:Factory Response[ReadInputRegistersResponse: 4]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!

It seems like the async client tries to decode the frame too early?

[stv0g]

I see the same behaviour in our setup.

I was hoping that disabling the strict mode to relax the intra character timing requirements could fix the issue.

However, creating the client with the strict=False setting is only supported in the synchronous version.

[dhoomakethu]

Fixed with e402d9f#diff-90d825c299aa37cc31eb357be29777fbR731. Now timeout could be passed as a kwarg during client initialization.