search

pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.22k stars 907 forks source link

ModbusRTUFramer.resetFrame()... Does not reset frame (buffer) #1917

Closed bsense-rius closed 8 months ago

bsense-rius commented 8 months ago

Versions

Pymodbus Specific

Description

The resetFrame function for ModbusRTUFramer does not actually reset the frame (the input buffer)!

As seen in the ModbusRtuFramer.resetFrame() attached below, it is clear that the buffer clearing perfomed at the base class ModbusFramer.resetFrame() is totally overriden by saving the current input buffer before resetting it to restore back immediately afterwards.

Therefore whenever using the ModbusRtuFramer and the resetFrame is to be called, for example in case a bad CRC is calculated, the call within the library is doing nothing, resulting in an input buffer that increases at every single modbus receive. This means that after a CRC error, all the next operations will be wrong because it will use a leaky buffer..

Previous to each Modbus operation I also used a resetFrame(), to ensure no dangling bytes were included. But obviously was useless.

I have to tell you that this drove me crazy. Difficult to spot as this seldom happens because usually there are no CRC errors or so. Don't know why it implements this override specifically for ModbusRtuFramer. Maybe to do some testing?

Code and Logs

# Direct from github repo (and on my local install)

    def resetFrame(self):
        """Reset the entire message frame.

        This allows us to skip over errors that may be in the stream.
        It is hard to know if we are simply out of sync or if there is
        an error in the stream as we have no way to check the start or
        end of the message (python just doesn't have the resolution to
        check for millisecond delays).
        """
        x = self._buffer
        super().resetFrame()
        self._buffer = x
janiversen commented 8 months ago

Pull requests are welcome.

janiversen commented 8 months ago

I vaguely remember that long time ago there was some problems with the rtu framer, but that is probably long gone.

lijianming1 commented 8 months ago

Dear @janiversen , hello. I have the same problems.

Versions Python: 3.9 OS: Ubutn 22.04 Pymodbus: 3.6.2 Client: rtu- sync

Description

When I send the first write command to the device via ModbusRTU protocol, an error occurs (because it's a read-only register). Subsequent commands that should execute correctly also result in errors. However, if the first command is changed to a read command (which can executes correctly), all subsequent commands can be executed correctly. And after using client.framer.resetFrame() following the first command that executed with an error, the output result still cannot be changed.

Log [first command that failed to execute]

/home/ming/anaconda3/envs/env39/bin/python /home/ming/Nextcloud/recentwork/programing/point_laser_measurement/scripts/plm/cip/api.py DEBUG:pymodbus.logging:[0] DEBUG:pymodbus.logging:Current transaction state - IDLE DEBUG:pymodbus.logging:Running transaction 1 DEBUG:pymodbus.logging:SEND: 0x1 0x6 0x0 0x0 0x0 0x0 0x89 0xca DEBUG:pymodbus.logging:New Transaction state "SENDING" DEBUG:pymodbus.logging:Changing transaction state from "SENDING" to "WAITING FOR REPLY" DEBUG:pymodbus.logging:Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" DEBUG:pymodbus.logging:RECV: 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:Processing: 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:Frame check failed, ignoring!! DEBUG:pymodbus.logging:Resetting frame - Current Frame in buffer - 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:Getting transaction 1 DEBUG:pymodbus.logging:Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" DEBUG:pymodbus.logging:[10] DEBUG:pymodbus.logging:Current transaction state - TRANSACTION_COMPLETE DEBUG:pymodbus.logging:Running transaction 2 DEBUG:pymodbus.logging:Clearing current Frame: - 0x2 0x0 0x1 DEBUG:pymodbus.logging:Resetting frame - Current Frame in buffer - 0x2 0x0 0x1 DEBUG:pymodbus.logging:SEND: 0x1 0x6 0x0 0x1 0x0 0xa 0x58 0xd DEBUG:pymodbus.logging:Changing state to IDLE - Last Frame End - None Current Time stamp - 1703489048.11645 DEBUG:pymodbus.logging:New Transaction state "SENDING" DEBUG:pymodbus.logging:Changing transaction state from "SENDING" to "WAITING FOR REPLY" [WriteRegister]: Received Modbus library error (Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response) DEBUG:pymodbus.logging:Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" DEBUG:pymodbus.logging:RECV: 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:Processing: 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:Frame - not ready DEBUG:pymodbus.logging:Getting transaction 1 DEBUG:pymodbus.logging:Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" DEBUG:pymodbus.logging:[0] DEBUG:pymodbus.logging:Current transaction state - TRANSACTION_COMPLETE DEBUG:pymodbus.logging:Running transaction 3 DEBUG:pymodbus.logging:Clearing current Frame: - 0x1 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:Resetting frame - Current Frame in buffer - 0x1 0x1 0x86 0x2 0x0 0x1 DEBUG:pymodbus.logging:SEND: 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22 DEBUG:pymodbus.logging:Changing state to IDLE - Last Frame End - None Current Time stamp - 1703489048.293182 DEBUG:pymodbus.logging:New Transaction state "SENDING" DEBUG:pymodbus.logging:Changing transaction state from "SENDING" to "WAITING FOR REPLY" [WriteRegister]: Received Modbus library error (Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response) DEBUG:pymodbus.logging:Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" DEBUG:pymodbus.logging:RECV: 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22 DEBUG:pymodbus.logging:Processing: 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22 DEBUG:pymodbus.logging:Frame - not ready DEBUG:pymodbus.logging:Getting transaction 1 DEBUG:pymodbus.logging:Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" DEBUG:pymodbus.logging:Current transaction state - TRANSACTION_COMPLETE DEBUG:pymodbus.logging:Running transaction 4 DEBUG:pymodbus.logging:Clearing current Frame: - 0x1 0x1 0x86 0x2 0x0 0x1 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22 DEBUG:pymodbus.logging:Resetting frame - Current Frame in buffer - 0x1 0x1 0x86 0x2 0x0 0x1 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22 DEBUG:pymodbus.logging:SEND: 0x1 0x3 0x0 0x0 0x0 0x2 0xc4 0xb DEBUG:pymodbus.logging:Changing state to IDLE - Last Frame End - None Current Time stamp - 1703489049.185923 DEBUG:pymodbus.logging:New Transaction state "SENDING" DEBUG:pymodbus.logging:Changing transaction state from "SENDING" to "WAITING FOR REPLY" [WriteRegister]: Received Modbus library error (Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response) {"OutDistance": 10, "SaveConfigure": 0, "error": {"OutDistance": -1}} Received Modbus library error (Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response {"OutDistance": -1, "SaveConfigure": 0, "error": {"OutDistance": -1}} DEBUG:pymodbus.logging:Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" DEBUG:pymodbus.logging:RECV: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 DEBUG:pymodbus.logging:Processing: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 DEBUG:pymodbus.logging:Frame - not ready DEBUG:pymodbus.logging:Getting transaction 1 DEBUG:pymodbus.logging:Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" DEBUG:pymodbus.logging:Resetting frame - Current Frame in buffer - 0x1 0x1 0x86 0x2 0x0 0x1 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4

Process finished with exit code 0

Log [first command that executed correctly]

/home/ming/anaconda3/envs/env39/bin/python /home/ming/Nextcloud/recentwork/programing/point_laser_measurement/scripts/plm/cip/api.py DEBUG:pymodbus.logging:Current transaction state - IDLE DEBUG:pymodbus.logging:Running transaction 1 DEBUG:pymodbus.logging:SEND: 0x1 0x3 0x0 0x0 0x0 0x2 0xc4 0xb DEBUG:pymodbus.logging:New Transaction state "SENDING" DEBUG:pymodbus.logging:Changing transaction state from "SENDING" to "WAITING FOR REPLY" {"OutDistance": 15000, "SaveConfigure": 0} DEBUG:pymodbus.logging:Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" DEBUG:pymodbus.logging:RECV: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 DEBUG:pymodbus.logging:Processing: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 DEBUG:pymodbus.logging:Getting Frame - 0x3 0x4 0x3a 0x98 0x0 0x0 DEBUG:pymodbus.logging:Factory Response[ReadHoldingRegistersResponse': 3] DEBUG:pymodbus.logging:Frame advanced, resetting header!! DEBUG:pymodbus.logging:Adding transaction 1 DEBUG:pymodbus.logging:Getting transaction 1 DEBUG:pymodbus.logging:Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" DEBUG:pymodbus.logging:[15000, 0] DEBUG:pymodbus.logging:handle: [b'\x00\x00', b':\x98'] DEBUG:pymodbus.logging:Current transaction state - TRANSACTION_COMPLETE DEBUG:pymodbus.logging:Running transaction 2 DEBUG:pymodbus.logging:SEND: 0x1 0x3 0x0 0x0 0x0 0x2 0xc4 0xb DEBUG:pymodbus.logging:Changing state to IDLE - Last Frame End - 1703490246.184508 Current Time stamp - 1703490246.185192 DEBUG:pymodbus.logging:Waiting for 3.5 char before next send - 1.75 ms DEBUG:pymodbus.logging:New Transaction state "SENDING" DEBUG:pymodbus.logging:Changing transaction state from "SENDING" to "WAITING FOR REPLY" {"OutDistance": 15000, "SaveConfigure": 0} DEBUG:pymodbus.logging:Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY" DEBUG:pymodbus.logging:RECV: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 DEBUG:pymodbus.logging:Processing: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 DEBUG:pymodbus.logging:Getting Frame - 0x3 0x4 0x3a 0x98 0x0 0x0 DEBUG:pymodbus.logging:Factory Response[ReadHoldingRegistersResponse': 3] DEBUG:pymodbus.logging:Frame advanced, resetting header!! DEBUG:pymodbus.logging:Adding transaction 1 DEBUG:pymodbus.logging:Getting transaction 1 DEBUG:pymodbus.logging:Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE" DEBUG:pymodbus.logging:[15000, 0] DEBUG:pymodbus.logging:handle: [b'\x00\x00', b':\x98']

Process finished with exit code 0

janiversen commented 8 months ago

Your problem start before the reset frame:

DEBUG:pymodbus.logging:Processing: 0x1 0x86 0x2 0x0 0x1

DEBUG:pymodbus.logging:Frame check failed, ignoring!!

Your device responds with an error, but the checksum is off...causing pymodbus to detect an invalid frame. In this case we do not want to reset the buffer because it might be we simply have not received the whole frame. Pymodbus will try to read more data and after a short while clean the buffer.

the app actually receives

[WriteRegister]: Received Modbus library error (Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response)

this happens when the next request is sent, and with that the buffer is cleared.

lijianming1 commented 8 months ago

Dear @janiversen, In debug mode, I traced the execution process. After executing the first erroneous command and then running the correct command, I found that the sent and received Modbus messages were correct. However, an error occurred internally when executing the funcion self.client.framer.processIncomingPacket(response, addTransaction, request.slave_id, tid=request.transaction_id), leading to the final error.

In the second image below, we can see: DEBUG.pymodbus.logging: SEND: 0x1 0x3 0x0 0x0 0x0 0x2 0xc4 0xb (this is a corect command) and DEBUG.pymodbus.logging: RECV: 0x1 0x3 0x4 0x3a 0x98 0x0 0x0 0x77 0x4 (this is the correct response). but then the execution process comes to self.client.framer.processIncomingPacket(response, addTransaction, request.slave_id, tid=request.transaction_id), I found the "self._buffer" value is b'\x01\x01\x86\x02\x00\x0x\x01\x06\x00\x80\x00\x00\x88' which should have been already cleared in the previous code. We can infer this from the logs: "*DEBUG:pymodbus.logging: Cearing current Frame: - 0x1 0x1 0x86 0x2 0x0 0x1 0x1 0x6 0x0 0x80 0x0 0x0 0x88 0x22" which lead "len(self._buffer) > self._hsize" "Frame - not ready" condition and break. finally process execute code: "response=ModbusIOException(last_exception, request.function_code)" and thowing an ModbusIOException. I feel the code is very comple and I still can't fix it out. Can you give me some further help?

lijianming1 commented 8 months ago

Screenshot from 2023-12-26 13-40-53_

lijianming1 commented 8 months ago

Screenshot from 2023-12-26 13-09-30_ Screenshot from 2023-12-26 14-42-25

janiversen commented 8 months ago

@bsense-rius is it correct that resetFrame does not reset the frame for serial connection. This is due to the fact how rs485 works.

If pymodbus is used as a slave on a rs485, it "sees" the traffic to all devices on the line, and thus have to hunt for a correct frame, resetting the frame just because it is not correct, might cut off the correct frame just one byte further. For that reason resetFrame is voided and replaced by a hunt frame method.

janiversen commented 8 months ago

@lijianming1 the crc is wrong in the first example, therefore it is rejected (and the app receives an error message correctly), what you see in the log after the "invalid frame" is a hunt for a legal frame.

It actually catches up again.

I have added a modification that secures a more rapid catch up.

the fix is in: https://github.com/pymodbus-dev/pymodbus/pull/1918 and available on dev.

lijianming1 commented 8 months ago

@janiversen thank you very much, it works now!