Frame check failed #1620

MGGEL · 2023-06-20T13:18:05Z

MGGEL
Jun 20, 2023

Hi,

I've startet with the Async Server example (https://pymodbus.readthedocs.io/en/v2.5.3/source/example/asynchronous_server.html) in Version 2.5.3.

from pymodbus.version import version
from pymodbus.server.asynchronous import StartTcpServer
from pymodbus.server.asynchronous import StartUdpServer
from pymodbus.server.asynchronous import StartSerialServer

from pymodbus.device import ModbusDeviceIdentification
from pymodbus.datastore import ModbusSequentialDataBlock
from pymodbus.datastore import ModbusSlaveContext, ModbusServerContext
from pymodbus.transaction import (ModbusRtuFramer,
                                  ModbusAsciiFramer,
                                  ModbusBinaryFramer)
import logging
FORMAT = ('%(asctime)-15s %(threadName)-15s'
          ' %(levelname)-8s %(module)-15s:%(lineno)-8s %(message)s')
logging.basicConfig(format=FORMAT)
log = logging.getLogger()
log.setLevel(logging.DEBUG)


def run_async_server():
    context = ModbusServerContext(slaves={
        unitId: ModbusSlaveContext(
           di=ModbusSequentialDataBlock(0, [17]*100),
           co=ModbusSequentialDataBlock(0, [17]*100),
           hr=ModbusSequentialDataBlock(0, [18]*100),
           ir=ModbusSequentialDataBlock(0, [17]*100),
           zero_mode=True
        ) for unitId in [0x01, 0x02]
    }, single=False)

    StartSerialServer(context, identity=identity, port='/dev/ttyAMA0', baudrate=19200, framer=ModbusRtuFramer, bytesize=8, stopbits=1, parity='E',timeout=1000)

if __name__ == "__main__":
    run_async_server()

I've checked every parameter several times at the Server and the Client. But I get only the message that the Frame check failed.
The Hardware is a Raspi 4.

The first few seconds it seems to work

2023-06-20 13:13:59,336 MainThread      INFO     asynchronous   :327      Starting Modbus Serial Server on /dev/ttyAMA0
2023-06-20 13:13:59,337 MainThread      DEBUG    asynchronous   :47       Client Connected [/dev/ttyAMA0]
2023-06-20 13:13:59,338 MainThread      DEBUG    asynchronous   :229      Running in Main thread
2023-06-20 13:13:59,902 MainThread      DEBUG    asynchronous   :64       Data Received: 0x1 0x3 0x0 0x9 0x0 0x4 0x94 0xb
2023-06-20 13:13:59,903 MainThread      DEBUG    rtu_framer     :185      Getting Frame - 0x3 0x0 0x9 0x0 0x4
2023-06-20 13:13:59,903 MainThread      DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
2023-06-20 13:13:59,903 MainThread      DEBUG    rtu_framer     :107      Frame advanced, resetting header!!
2023-06-20 13:13:59,903 MainThread      DEBUG    context        :64       validate: fc-[3] address-9: count-4
2023-06-20 13:13:59,904 MainThread      DEBUG    context        :78       getValues fc-[3] address-9: count-4
2023-06-20 13:13:59,904 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'
2023-06-20 13:14:00,121 MainThread      DEBUG    asynchronous   :64       Data Received: 0x1 0x3 0x0 0x9 0x0 0x4 0x94 0xb
2023-06-20 13:14:00,121 MainThread      DEBUG    rtu_framer     :185      Getting Frame - 0x3 0x0 0x9 0x0 0x4
2023-06-20 13:14:00,122 MainThread      DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
2023-06-20 13:14:00,122 MainThread      DEBUG    rtu_framer     :107      Frame advanced, resetting header!!
2023-06-20 13:14:00,122 MainThread      DEBUG    context        :64       validate: fc-[3] address-9: count-4
2023-06-20 13:14:00,122 MainThread      DEBUG    context        :78       getValues fc-[3] address-9: count-4
2023-06-20 13:14:00,122 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'
2023-06-20 13:14:00,340 MainThread      DEBUG    asynchronous   :64       Data Received: 0x1 0x3 0x0 0x9 0x0 0x4 0x94 0xb
2023-06-20 13:14:00,340 MainThread      DEBUG    rtu_framer     :185      Getting Frame - 0x3 0x0 0x9 0x0 0x4
2023-06-20 13:14:00,341 MainThread      DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
2023-06-20 13:14:00,341 MainThread      DEBUG    rtu_framer     :107      Frame advanced, resetting header!!
2023-06-20 13:14:00,342 MainThread      DEBUG    context        :64       validate: fc-[3] address-9: count-4
2023-06-20 13:14:00,342 MainThread      DEBUG    context        :78       getValues fc-[3] address-9: count-4
2023-06-20 13:14:00,343 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'
2023-06-20 13:14:00,560 MainThread      DEBUG    asynchronous   :64       Data Received: 0x1 0x3 0x0 0x9 0x0 0x4 0x94 0xb
2023-06-20 13:14:00,561 MainThread      DEBUG    rtu_framer     :185      Getting Frame - 0x3 0x0 0x9 0x0 0x4
2023-06-20 13:14:00,561 MainThread      DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
2023-06-20 13:14:00,561 MainThread      DEBUG    rtu_framer     :107      Frame advanced, resetting header!!
2023-06-20 13:14:00,561 MainThread      DEBUG    context        :64       validate: fc-[3] address-9: count-4
2023-06-20 13:14:00,561 MainThread      DEBUG    context        :78       getValues fc-[3] address-9: count-4
2023-06-20 13:14:00,561 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'
2023-06-20 13:14:00,779 MainThread      DEBUG    asynchronous   :64       Data Received: 0x1 0x3 0x0 0x9 0x0 0x4 0x94 0xb
2023-06-20 13:14:00,779 MainThread      DEBUG    rtu_framer     :185      Getting Frame - 0x3 0x0 0x9 0x0 0x4
2023-06-20 13:14:00,779 MainThread      DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
2023-06-20 13:14:00,779 MainThread      DEBUG    rtu_framer     :107      Frame advanced, resetting header!!
2023-06-20 13:14:00,779 MainThread      DEBUG    context        :64       validate: fc-[3] address-9: count-4
2023-06-20 13:14:00,780 MainThread      DEBUG    context        :78       getValues fc-[3] address-9: count-4
2023-06-20 13:14:00,780 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'

After a few seconds the failure begins.

2023-06-20 13:14:38,217 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'
2023-06-20 13:14:38,434 MainThread      DEBUG    asynchronous   :64       Data Received: 0x1 0x3 0x0 0x9 0x0 0x4 0x94 0xb
2023-06-20 13:14:38,435 MainThread      DEBUG    rtu_framer     :185      Getting Frame - 0x3 0x0 0x9 0x0 0x4
2023-06-20 13:14:38,435 MainThread      DEBUG    factory        :137      Factory Request[ReadHoldingRegistersRequest: 3]
2023-06-20 13:14:38,436 MainThread      DEBUG    rtu_framer     :107      Frame advanced, resetting header!!
2023-06-20 13:14:38,436 MainThread      DEBUG    context        :64       validate: fc-[3] address-9: count-4
2023-06-20 13:14:38,436 MainThread      DEBUG    context        :78       getValues fc-[3] address-9: count-4
2023-06-20 13:14:38,437 MainThread      DEBUG    asynchronous   :102      send: b'01030800120012001200123fdd'
2023-06-20 13:14:39,357 MainThread      DEBUG    asynchronous   :64       Data Received: 0x14 0x40 0x0 0x6b 0x14 0x40 0xa0 0xe1 0xfe
2023-06-20 13:14:39,358 MainThread      DEBUG    rtu_framer     :237      Frame check failed, ignoring!!
2023-06-20 13:14:39,358 MainThread      DEBUG    rtu_framer     :120      Resetting frame - Current Frame in buffer - 0x14 0x40 0x0 0x6b 0x14 0x40 0xa0 0xe1 0xfe
2023-06-20 13:14:40,757 MainThread      DEBUG    asynchronous   :64       Data Received: 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:40,758 MainThread      DEBUG    rtu_framer     :237      Frame check failed, ignoring!!
2023-06-20 13:14:40,758 MainThread      DEBUG    rtu_framer     :120      Resetting frame - Current Frame in buffer - 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:42,158 MainThread      DEBUG    asynchronous   :64       Data Received: 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:42,159 MainThread      DEBUG    rtu_framer     :237      Frame check failed, ignoring!!
2023-06-20 13:14:42,159 MainThread      DEBUG    rtu_framer     :120      Resetting frame - Current Frame in buffer - 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:43,559 MainThread      DEBUG    asynchronous   :64       Data Received: 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:43,560 MainThread      DEBUG    rtu_framer     :237      Frame check failed, ignoring!!
2023-06-20 13:14:43,560 MainThread      DEBUG    rtu_framer     :120      Resetting frame - Current Frame in buffer - 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:46,118 MainThread      DEBUG    asynchronous   :64       Data Received: 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b
2023-06-20 13:14:46,119 MainThread      DEBUG    rtu_framer     :237      Frame check failed, ignoring!!
2023-06-20 13:14:46,119 MainThread      DEBUG    rtu_framer     :120      Resetting frame - Current Frame in buffer - 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b

Do you have any idea what causes the failure?

Thank you in advance!

Answered by janiversen

Jun 27, 2023

That is highly unlikely, at least if this is a pymodbus problem, because the source code is quite different,

We are new at version 3.3.2, you might want to give that a try, and provide the debug log.

If the result as in the original post, the problem is the same pymodbus receives garbled data, which is caused by cabling or the rs485 adapter. Since it seems to works the first few seconds it does not look like a parameter problem, nor a problem in pymodbus.

View full answer

janiversen · 2023-06-20T14:10:57Z

janiversen
Jun 20, 2023
Maintainer

It seems your client starts sending faulty packages.

BUT we no longer support version 2.5.3, especially the async part have changed a lot between 2.5.3 and current release 3.3.1, so first advice is to update the library.

0 replies

MGGEL · 2023-06-21T11:59:27Z

MGGEL
Jun 21, 2023
Author

I've updatet to release 3.3.1 and got the following problems:

The Source:

import asyncio
import logging

from pymodbus.framer.rtu_framer import ModbusRtuFramer
from pymodbus.server import StartAsyncSerialServer
from pymodbus import __version__ as pymodbus_version

logging.basicConfig(
    format="[%(asctime)s] [%(levelname)s] [%(name)s] %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S %z",
    level=logging.INFO,
)
log = logging.getLogger(__name__)


async def modbus_slave():
    return await StartAsyncSerialServer(
        framer=ModbusRtuFramer,
        port="/dev/ttyAMA0",
        baudrate=19200,
        stopbits=1,
        bytesize=8,
        parity="E",
    )


def sanity():
    log.info(f"✅ Here I am!")
    asyncio.run(modbus_slave())
    log.info(f"❌ I'm going insane!")
    print(pymodbus_version)
sanity()

The failure:

  File "/usr/lib/python3.9/site-packages/pymodbus/server/async_io.py", line 969, in _connect
    self.transport, self.protocol = await create_serial_connection(
  File "/usr/lib/python3.9/site-packages/pymodbus/transport/serial_asyncio/__init__.py", line 466, in create_serial_connection
    serial_instance = serial.serial_for_url(*args, **kwargs)
NameError: name 'serial' is not defined

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/modbus_test/server3.py", line 32, in <module>
    sanity()
  File "/home/pi/modbus_test/server3.py", line 29, in sanity
    asyncio.run(modbus_slave())
  File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/home/pi/modbus_test/server3.py", line 17, in modbus_slave
    return await StartAsyncSerialServer(
  File "/usr/lib/python3.9/site-packages/pymodbus/server/async_io.py", line 1233, in StartAsyncSerialServer
    await server.start()
  File "/usr/lib/python3.9/site-packages/pymodbus/server/async_io.py", line 953, in start
    await self._connect()
  File "/usr/lib/python3.9/site-packages/pymodbus/server/async_io.py", line 979, in _connect
    except serial.serialutil.SerialException as exc:
NameError: name 'serial' is not defined

I've commented out the lines in async_io.py and got the following output:

[2023-06-21 11:55:17 +0000] [INFO] [__main__] ✅ Here I am!
[2023-06-21 11:55:17 +0000] [INFO] [pymodbus.logging] Server(Serial) listening.
[2023-06-21 11:55:17 +0000] [INFO] [__main__] ❌ I'm going insane!
3.3.1

So the Server doesn't wait for incomming connections.

1 reply

janiversen Jun 21, 2023
Maintainer

I think it is an issue we already solved, please try dev.

MGGEL · 2023-06-21T12:47:27Z

MGGEL
Jun 21, 2023
Author

Same failure:

NameError: name 'serial' is not defined

[2023-06-21 12:46:40 +0000] [INFO] [__main__] ✅ Here I am!
[2023-06-21 12:46:40 +0000] [INFO] [pymodbus.logging] Server(Serial) listening.
[2023-06-21 12:46:40 +0000] [INFO] [__main__] ❌ I'm going insane!
3.4.0dev

7 replies

MGGEL Jun 26, 2023
Author

Im running from one to another Problem ...
I've installed pymodbus[serial] the python error doesn't show up anymore.

Now I've build a small test: Raspi4 connected by RS485 with an serial/USB converter attached to my Laptop.
My Laptop sends the following Message which should collect the data:

But instead of the send Message the Raspi gets the following, and only every second request:

[2023-06-26 12:22:27 +0000] [DEBUG] [asyncio] Using selector: EpollSelector
[2023-06-26 12:22:27 +0000] [INFO] [pymodbus.logging] Server(Serial) listening.
[2023-06-26 12:22:27 +0000] [DEBUG] [pymodbus.logging] Serial connection opened on port: /dev/ttyAMA0
[2023-06-26 12:22:27 +0000] [DEBUG] [pymodbus.logging] Serial connection established
[2023-06-26 12:22:31 +0000] [DEBUG] [pymodbus.logging] Handling data: 0x14 0x40 0x0 0x6b 0x14 0x40 0x0 0x6b

The Source Code:

import asyncio
import logging
from pymodbus.framer.rtu_framer import ModbusRtuFramer
from pymodbus.server import StartAsyncSerialServer
from pymodbus import __version__ as pymodbus_version
from pymodbus.datastore import (
    ModbusSequentialDataBlock,
    ModbusServerContext,
    ModbusSlaveContext,
    ModbusSparseDataBlock,
)
from pymodbus.device import ModbusDeviceIdentification


logging.basicConfig(
    format="[%(asctime)s] [%(levelname)s] [%(name)s] %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S %z",
    level=logging.DEBUG,
)
log = logging.getLogger(__name__)


async def modbus_slave():
    datablock = ModbusSequentialDataBlock(0x00, [18] * 100)
    slaveContext = ModbusSlaveContext(di=datablock, co=datablock, hr=datablock, ir=datablock)
    slaves  = {
         0x01: slaveContext,
         0x02: slaveContext,
    }

    context = ModbusServerContext(slaves=slaves, single=False)

    identity = ModbusDeviceIdentification(
        info_name={
            "VendorName": "Pymodbus",
            "ProductCode": "PM",
            "VendorUrl": "https://github.com/pymodbus-dev/pymodbus/",
            "ProductName": "Pymodbus Server",
            "ModelName": "Pymodbus Server",
            "MajorMinorRevision": pymodbus_version,
        }
    )

    return await StartAsyncSerialServer(
        context=context,
        identity=identity,
        framer=ModbusRtuFramer,
        port="/dev/ttyAMA0",
        baudrate=19200,
        stopbits=1,
        bytesize=8,
        parity="E",
    )


def start():
    print(pymodbus_version)
    asyncio.run(modbus_slave())
start()

The Config of the Tool on my Laptop:

Do you have any idea what causes this Problem?

janiversen Jun 26, 2023
Maintainer

Seems one of you usb adapters is doing something nasty, because what you send is not what is being received.

I assume you have a Rs485 adapter in each end, be aware that some adapters can only be used as master (controlling) the rs485. On the RPI I have had problems with a HAT and replaced it with a serial converter.

Another possibility likely is that your rs485 cabling is not correct.

I often try to test on the same computer using 2 usb adapters, that excludes a lot of potential problems.

Hope that helps.

MGGEL Jun 26, 2023
Author

It seems to me that it is the same failure as the first Post with the old version. In that constelation there was no adapter in use.
In the first Post it was an Wago PLC and the Raspi CM4 Module. I was able to collect data from the Wago PLC when it was a slave. Then i switched the roles so the CM4 module was the slave. But that didnt Work.
The last test was with the same CM4 Module but with my Laptop and a RS485 adapter.

I've testet and turned the cables several times.

janiversen Jun 27, 2023
Maintainer

That is highly unlikely, at least if this is a pymodbus problem, because the source code is quite different,

We are new at version 3.3.2, you might want to give that a try, and provide the debug log.

If the result as in the original post, the problem is the same pymodbus receives garbled data, which is caused by cabling or the rs485 adapter. Since it seems to works the first few seconds it does not look like a parameter problem, nor a problem in pymodbus.

Answer selected by janiversen

janiversen · 2024-01-13T16:07:02Z

janiversen
Jan 13, 2024
Maintainer

you have not installed pyserial, see our readme.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Frame check failed #1620

{{title}}

Replies: 4 comments 8 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Frame check failed #1620

MGGEL Jun 20, 2023

Replies: 4 comments · 8 replies

janiversen Jun 20, 2023 Maintainer

MGGEL Jun 21, 2023 Author

janiversen Jun 21, 2023 Maintainer

MGGEL Jun 21, 2023 Author

MGGEL Jun 26, 2023 Author

janiversen Jun 26, 2023 Maintainer

MGGEL Jun 26, 2023 Author

janiversen Jun 27, 2023 Maintainer

janiversen Jan 13, 2024 Maintainer

MGGEL
Jun 20, 2023

Replies: 4 comments 8 replies

janiversen
Jun 20, 2023
Maintainer

MGGEL
Jun 21, 2023
Author

janiversen Jun 21, 2023
Maintainer

MGGEL
Jun 21, 2023
Author

MGGEL Jun 26, 2023
Author

janiversen Jun 26, 2023
Maintainer

MGGEL Jun 26, 2023
Author

janiversen Jun 27, 2023
Maintainer

janiversen
Jan 13, 2024
Maintainer