Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Broadcast responses handling in Sync RTU #383

Closed
drakes00 opened this issue Feb 1, 2019 · 4 comments
Closed

Broadcast responses handling in Sync RTU #383

drakes00 opened this issue Feb 1, 2019 · 4 comments

Comments

@drakes00
Copy link

drakes00 commented Feb 1, 2019

Versions

  • Python: 3.5.3
  • OS: Debian GNU/Linux 9.7 (stretch) // Linux hostname 4.9.0-8-amd64 Fix Documentation for Client.Sync #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64 GNU/Linux
  • Pymodbus: 2.1.0 and 2.2.0
  • Modbus Hardware (if used): RS485 cable with 3 ends in order to link one client with two servers (see below)

Pymodbus Specific

  • Server: tcp/rtu/ascii - sync/async -- Sync RTU x2
  • Client: tcp/rtu/ascii - sync/async -- Sync RTU

Description

What were you trying, what has happened, what went wrong, and what did you expect?

One client speaks with two servers. Servers have different unit ids (e.g., server 1 has unit id 1 and server 2 has unit id 2). When client requests on server 1, server 2 also receives request and drops it due to code in ModbusRtuFramer.processIncommingPacket:218 (which is good).

if self._validate_unit_id(unit, single):                                                      
    self._process(callback)                                                                   
else:                                                                                         
    _logger.debug("Not a valid unit id - {}, "                                                
                  "ignoring!!".format(self._header['uid']))

However, server 2 also receives answer from server 1 which is badly parsed because decoder is a ServerDecoder which doesn't know how to handle responses. Thus CRC verification fails and most likely end-up with the same issues raised in #376 and #356.

According to PR, this should be fixed in release 2.2.0.
Can you confirm my analysis of the problem and is 2.2.0 scheduled?
I was also wondering if it wouldn't be easier to just validate unit id before even computing CRC?

Also, maybe I am doing things wrong on having

Thanks a lot,
Best

@dhoomakethu
Copy link
Contributor

Interesting bug report, are you running pymodbus rtu server with one unit on the same port in two numbers or just one pymodbus server with 2 units ? Could you please share the logs of the second server receiving the response ? Also the code for your server as well.

@drakes00
Copy link
Author

drakes00 commented Feb 4, 2019

I have three processes. One client and two servers (one with units 0x01 and 0x02 and the other with units 0x03 and 0x04). Basically all messages are broadcated to all processes including responses. However as servers have a ServerDecoder they can't handle responses which appear to have a bad CRC. The worst part is that if a response is a the start of the buffer with a valid request after, then the whole buffer is erased when calling self.resetFrame.

Minimal working example

Code for servers (replace unit IDs with 3 and 4 for other server and /dev/ttyUSB2):

import logging

from    pymodbus.server.sync        import ModbusSerialServer
from    pymodbus.datastore          import ModbusSequentialDataBlock
from    pymodbus.datastore          import ModbusSlaveContext, ModbusServerContext
from    pymodbus.transaction        import ModbusRtuFramer

if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG)

    # Initialise slave and its components
    context = ModbusServerContext(slaves={
        unitId: ModbusSlaveContext(
            di=ModbusSequentialDataBlock(0x00, [False]*0x10),
            co=ModbusSequentialDataBlock(0x00, [False]*0x10),
            hr=ModbusSequentialDataBlock(0x00, [0]*0x10),
            ir=ModbusSequentialDataBlock(0x00, [0]*0x10),
            zero_mode=True
        ) for unitId in [0x01, 0x02]
    }, single=False)
    slave = ModbusSerialServer(
        context,
        ModbusRtuFramer,
        ignore_missing_slaves=True,
        port='/dev/ttyUSB1',
        baudrate=115200,
        timeout=2,
    )

    # Initialize channel
    slave.serve_forever()

Code for client:

import logging

from    pymodbus.client.sync        import ModbusSerialClient

if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG)

    client = ModbusSerialClient(method='rtu', port='/dev/ttyUSB0', timeout=2, baudrate=115200)
    client.connect()
    client.read_coils(0x01, 1, unit=0x01).bits[0]
    client.read_coils(0x02, 1, unit=0x02).bits[0]
    client.read_coils(0x03, 1, unit=0x03).bits[0]
    client.read_coils(0x04, 1, unit=0x04).bits[0]
    client.close()

Logs

Log for client:

DEBUG:pymodbus.transaction:Current transaction state - IDLE
DEBUG:pymodbus.transaction:Running transaction 1
DEBUG:pymodbus.transaction:SEND: 0x1 0x1 0x0 0x1 0x0 0x1 0xac 0xa
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 0x1 0x1 0x0 0x51 0x88
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x1 0x0
DEBUG:pymodbus.factory:Factory Response[ReadCoilsResponse: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 2
DEBUG:pymodbus.transaction:SEND: 0x2 0x1 0x0 0x2 0x0 0x1 0x5c 0x39
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1549270868.803964, Current Time stamp - 1549270868.804972
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 1.75 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Transaction failed. (Modbus Error: [Invalid Message] Incomplete message received, expected at least 2 bytes (0 received))
DEBUG:pymodbus.framer.rtu_framer:Frame - [b''] not ready
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
Traceback (most recent call last):
File "plc.py", line 11, in
client.read_coils(0x02, 1, unit=0x02).bits[0]
AttributeError: 'ModbusIOException' object has no attribute 'bits'

Logs for server 1:

DEBUG:pymodbus.server.sync:Client Connected [/dev/ttyUSB1:/dev/ttyUSB1]
DEBUG:pymodbus.server.sync:Started thread to serve client
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x0 0x1 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.datastore.context:validate[1] 1:1
DEBUG:pymodbus.datastore.context:getValues[1] 1:1
DEBUG:pymodbus.server.sync:send: b'010101005188'
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x0 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.datastore.context:validate[1] 2:1
DEBUG:pymodbus.datastore.context:getValues[1] 2:1
DEBUG:pymodbus.server.sync:send: b'0201010051cc'

Logs for server 2:

DEBUG:pymodbus.server.sync:Client Connected [/dev/ttyUSB2:/dev/ttyUSB2]
DEBUG:pymodbus.server.sync:Started thread to serve client
DEBUG:pymodbus.framer.rtu_framer:Not a valid unit id - 1, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x1 0x0 0x1 0x0 0x1 0xac 0xa

With pymodbus 2.2.0.rc2 (6960d9c)

Logs for server 1:

DEBUG:pymodbus.server.sync:Client Connected [/dev/ttyUSB1:/dev/ttyUSB1]
DEBUG:pymodbus.server.sync:Started thread to serve client
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x0 0x1 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadCoilsRequest: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.datastore.context:validate: fc-[1] address-1: count-1
DEBUG:pymodbus.datastore.context:getValues fc-[1] address-1: count-1
DEBUG:pymodbus.server.sync:send: [ReadBitResponse(1)]- b'010101005188'
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x0 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadCoilsRequest: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.datastore.context:validate: fc-[1] address-2: count-1
DEBUG:pymodbus.datastore.context:getValues fc-[1] address-2: count-1
DEBUG:pymodbus.server.sync:send: [ReadBitResponse(1)]- b'0201010051cc'
DEBUG:pymodbus.framer.rtu_framer:Not a valid unit id - 3, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x3 0x1 0x0 0x3 0x0 0x1 0xc 0x28

Logs for server 2:

DEBUG:pymodbus.server.sync:Client Connected [/dev/ttyUSB2:/dev/ttyUSB2]
DEBUG:pymodbus.server.sync:Started thread to serve client
DEBUG:pymodbus.framer.rtu_framer:Not a valid unit id - 1, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x1 0x0 0x1 0x0 0x1 0xac 0xa 0x1 0x1 0x1 0x0 0x51 0x88 0x2 0x1 0x0 0x2 0x0 0x1 0x5c 0x39

Logs for client:

DEBUG:pymodbus.transaction:Current transaction state - IDLE
DEBUG:pymodbus.transaction:Running transaction 1
DEBUG:pymodbus.transaction:SEND: 0x1 0x1 0x0 0x1 0x0 0x1 0xac 0xa
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 0x1 0x1 0x0 0x51 0x88
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x1 0x0
DEBUG:pymodbus.factory:Factory Response[ReadCoilsResponse: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 2
DEBUG:pymodbus.transaction:SEND: 0x2 0x1 0x0 0x2 0x0 0x1 0x5c 0x39
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1549271278.507842, Current Time stamp - 1549271278.508914
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 1.75 ms
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: 0x2 0x1 0x1 0x0 0x51 0xcc
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x1 0x0
DEBUG:pymodbus.factory:Factory Response[ReadCoilsResponse: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 2
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 3
DEBUG:pymodbus.transaction:SEND: 0x3 0x1 0x0 0x3 0x0 0x1 0xc 0x28
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1549271280.507854, Current Time stamp - 1549271280.508761
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 1.75 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Transaction failed. (Modbus Error: [Invalid Message] Incomplete message received, expected at least 2 bytes (0 received))
DEBUG:pymodbus.framer.rtu_framer:Frame - [b''] not ready
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
Traceback (most recent call last):
File "plc.py", line 12, in
client.read_coils(0x03, 1, unit=0x03).bits[0]
AttributeError: 'ModbusIOException' object has no attribute 'bits' b

Fix similar to #376

    def processIncomingPacket(self, data, callback, unit, **kwargs):
        if not isinstance(unit, (list, tuple)):
            unit = [unit]
        self.addToFrame(data)
        single = kwargs.get("single", False)
        if self.isFrameReady():
            if self.checkFrame():
                if self._validate_unit_id(unit, single):
                    self._process(callback)
                else:
                    _logger.debug("Not a valid unit id - {}, "
                                  "ignoring!!".format(self._header['uid']))
                    self.resetFrame()
            else:
                _logger.debug("Invalid CRC")
                self.resetFrame()
        else:
            _logger.debug("Frame - [{}] not ready".format(data))

Logs for client:

DEBUG:pymodbus.transaction:Current transaction state - IDLE
DEBUG:pymodbus.transaction:Running transaction 1
DEBUG:pymodbus.transaction:SEND: 0x1 0x1 0x0 0x1 0x0 0x1 0xac 0xa
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 0x1 0x1 0x0 0x51 0x88
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x1 0x0
DEBUG:pymodbus.factory:Factory Response[ReadCoilsResponse: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 1
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 2
DEBUG:pymodbus.transaction:SEND: 0x2 0x1 0x0 0x2 0x0 0x1 0x5c 0x39
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1549272150.88777, Current Time stamp - 1549272150.888774
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 1.75 ms
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: 0x2 0x1 0x1 0x0 0x51 0xcc
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x1 0x0
DEBUG:pymodbus.factory:Factory Response[ReadCoilsResponse: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 2
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 3
DEBUG:pymodbus.transaction:SEND: 0x3 0x1 0x0 0x3 0x0 0x1 0xc 0x28
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1549272152.887461, Current Time stamp - 1549272152.888536
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 1.75 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Transaction failed. (Modbus Error: [Invalid Message] Incomplete message received, expected at least 2 bytes (0 received))
DEBUG:pymodbus.framer.rtu_framer:Frame - [b''] not ready
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
Traceback (most recent call last):
File "plc.py", line 12, in
client.read_coils(0x03, 1, unit=0x03).bits[0]
AttributeError: 'ModbusIOException' object has no attribute 'bits'

Logs for server 1:

DEBUG:pymodbus.server.sync:Client Connected [/dev/ttyUSB1:/dev/ttyUSB1]
DEBUG:pymodbus.server.sync:Started thread to serve client
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x0 0x1 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadCoilsRequest: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.datastore.context:validate: fc-[1] address-1: count-1
DEBUG:pymodbus.datastore.context:getValues fc-[1] address-1: count-1
DEBUG:pymodbus.server.sync:send: [ReadBitResponse(1)]- b'010101005188'
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x1 0x0 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadCoilsRequest: 1]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.datastore.context:validate: fc-[1] address-2: count-1
DEBUG:pymodbus.datastore.context:getValues fc-[1] address-2: count-1
DEBUG:pymodbus.server.sync:send: [ReadBitResponse(1)]- b'0201010051cc'
DEBUG:pymodbus.framer.rtu_framer:Not a valid unit id - 3, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x3 0x1 0x0 0x3 0x0 0x1 0xc 0x28

Logs for server2:

DEBUG:pymodbus.server.sync:Client Connected [/dev/ttyUSB2:/dev/ttyUSB2]
DEBUG:pymodbus.server.sync:Started thread to serve client
DEBUG:pymodbus.framer.rtu_framer:Not a valid unit id - 1, ignoring!!
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x1 0x1 0x0 0x1 0x0 0x1 0xac 0xa 0x1 0x1 0x1 0x0 0x51 0x88 0x2 0x1 0x0 0x2 0x0 0x1 0x5c 0x39
DEBUG:pymodbus.framer.rtu_framer:Invalid CRC
DEBUG:pymodbus.framer.rtu_framer:Resetting frame - Current Frame in buffer - 0x2 0x1 0x1 0x0 0x51 0xcc 0x3 0x1 0x0 0x3 0x0 0x1 0xc 0x28

As I'm calling slef.resetFrame in case of bad CRC, the whole frame is rejected event if a good message follows in the buffer (ass in log of server2 with unit 0x03). I was thinking about calling self.advanceFrame instead to just burn useless message and not all buffer but as it relies on length in header, responses will still be removed incorrectly. Other possiblity, make use of self._end and insert delimiter in buffer to remove proper packages. Other possiblity, allow servers to decode requests and responses?

@github-actions
Copy link

github-actions bot commented Mar 3, 2021

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

@github-actions
Copy link

github-actions bot commented Mar 8, 2021

This issue was closed because it has been stalled for 5 days with no activity.

@github-actions github-actions bot closed this as completed Mar 8, 2021
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 21, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

2 participants