search

pymodbus-dev / pymodbus

A full modbus protocol written in python
Other
2.25k stars 921 forks source link

Sporadic response decoding failures #2083

Closed RoGu777 closed 7 months ago

RoGu777 commented 7 months ago

Dear pymodbus community,

I have connected my aqotec district heating device to HomeAssistant which uses pymodbus library. Data is being read out, but not constantly. Some response processing (around 30-40%) fails with the error: Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response.

see logs for the complete messages.

Any help is appreciated. Thanks in advance!

Versions

Pymodbus Specific

Code and Logs

Configuration:

   type: serial
   port: /dev/ttyUSB1
   baudrate: 115200
   bytesize: 8
   method: rtu
   parity: N
   stopbits: 1

Successful read log:

2024-03-05 18:02:45.793 DEBUG (SyncWorker_14) [pymodbus.logging] Current transaction state - TRANSACTION_COMPLETE
2024-03-05 18:02:45.794 DEBUG (SyncWorker_14) [pymodbus.logging] Running transaction 94
2024-03-05 18:02:45.794 DEBUG (SyncWorker_14) [pymodbus.logging] Clearing current Frame: - 0x2 0x0 0x0
2024-03-05 18:02:45.794 DEBUG (SyncWorker_14) [pymodbus.logging] Resetting frame - Current Frame in buffer - 0x2 0x0 0x0
2024-03-05 18:02:45.794 DEBUG (SyncWorker_14) [pymodbus.logging] SEND: 0xa 0x3 0xaa 0xe6 0x0 0x8 0x85 0x58
2024-03-05 18:02:45.794 DEBUG (SyncWorker_14) [pymodbus.logging] Resetting frame - Current Frame in buffer - 0x2 0x0 0x0
2024-03-05 18:02:45.794 DEBUG (SyncWorker_14) [pymodbus.logging] Changing state to IDLE - Last Frame End - None Current Time stamp - 1709658165.794716
2024-03-05 18:02:45.797 DEBUG (SyncWorker_14) [pymodbus.logging] New Transaction state "SENDING"
2024-03-05 18:02:45.797 DEBUG (SyncWorker_14) [pymodbus.logging] Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-03-05 18:02:45.810 DEBUG (SyncWorker_14) [pymodbus.logging] Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-03-05 18:02:45.810 DEBUG (SyncWorker_14) [pymodbus.logging] RECV: 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66 0x23
2024-03-05 18:02:45.810 DEBUG (SyncWorker_14) [pymodbus.logging] Processing: 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66 0x23
2024-03-05 18:02:45.810 DEBUG (SyncWorker_14) [pymodbus.logging] Getting Frame - 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0
2024-03-05 18:02:45.810 DEBUG (SyncWorker_14) [pymodbus.logging] Factory Response[ReadHoldingRegistersResponse': 3]
2024-03-05 18:02:45.810 DEBUG (SyncWorker_14) [pymodbus.logging] Frame advanced, resetting header!!
2024-03-05 18:02:45.811 DEBUG (SyncWorker_14) [pymodbus.logging] Adding transaction 10
2024-03-05 18:02:45.811 DEBUG (SyncWorker_14) [pymodbus.logging] Getting transaction 10
2024-03-05 18:02:45.811 DEBUG (SyncWorker_14) [pymodbus.logging] Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
2024-03-05 18:02:45.845 DEBUG (MainThread) [homeassistant.components.modbus.sensor] Manually updated modbus_zaehler1 data

Failed read log:


2024-03-05 18:02:55.806 DEBUG (SyncWorker_10) [pymodbus.logging] Current transaction state - TRANSACTION_COMPLETE
2024-03-05 18:02:55.806 DEBUG (SyncWorker_10) [pymodbus.logging] Running transaction 105
2024-03-05 18:02:55.806 DEBUG (SyncWorker_10) [pymodbus.logging] SEND: 0xa 0x3 0xaa 0xe6 0x0 0x8 0x85 0x58
2024-03-05 18:02:55.806 DEBUG (SyncWorker_10) [pymodbus.logging] Resetting frame - Current Frame in buffer -
2024-03-05 18:02:55.806 DEBUG (SyncWorker_10) [pymodbus.logging] Changing state to IDLE - Last Frame End - 1709658175.772512 Current Time stamp - 1709658175.806616
2024-03-05 18:02:55.806 DEBUG (SyncWorker_10) [pymodbus.logging] New Transaction state "SENDING"
2024-03-05 18:02:55.806 WARNING (SyncWorker_10) [pymodbus.logging] Cleanup recv buffer before send: 0xff
2024-03-05 18:02:55.807 DEBUG (SyncWorker_10) [pymodbus.logging] Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-03-05 18:02:55.818 DEBUG (SyncWorker_10) [pymodbus.logging] Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-03-05 18:02:55.818 DEBUG (SyncWorker_10) [pymodbus.logging] RECV: 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xff 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66
2024-03-05 18:02:55.818 DEBUG (SyncWorker_10) [pymodbus.logging] Processing: 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xff 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66
2024-03-05 18:02:55.819 DEBUG (SyncWorker_10) [pymodbus.logging] Frame check failed, ignoring!!
2024-03-05 18:02:55.819 DEBUG (SyncWorker_10) [pymodbus.logging] Resetting frame - Current Frame in buffer - 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xff 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66
2024-03-05 18:02:55.819 DEBUG (SyncWorker_10) [pymodbus.logging] Getting transaction 10
2024-03-05 18:02:55.820 DEBUG (SyncWorker_10) [pymodbus.logging] Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
2024-03-05 18:02:55.820 ERROR (SyncWorker_10) [homeassistant.components.modbus.modbus] Pymodbus: modbus_fernwaerme: Error: device: 10 address: 43750 -> Modbus Error: [Input/Output] No Response received from the remote slave/Unable to decode response
2024-03-05 18:02:55.852 DEBUG (MainThread) [homeassistant.components.modbus.sensor] Manually updated modbus_zaehler1 data
janiversen commented 7 months ago

That sounds like a potential bug, let me have a look, but a bit later.

janiversen commented 7 months ago

The issue really belongs in Homeassistant, provided you use the modbus integration....if not I would like to know which integration you use ?

I assume you are aware that if we solve it here, it will NOT be solved in HA, unless the modbus integration decides to upgrade.

RoGu777 commented 7 months ago

yes, I am using the modbus integration of HomeAssistant, which itself uses pymodbus:

https://www.home-assistant.io/integrations/modbus/

Yes, I am aware of the needed upgrade

janiversen commented 7 months ago

The problem seems to be your serial line or USB converter:

This is the good one:

SEND: 0xa 0x3 0xaa 0xe6 0x0 0x8 0x85 0x58
RECV: 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66 0x23

Now you will note a couple of 0xff with the bad frame:

SEND: 0xa 0x3 0xaa 0xe6 0x0 0x8 0x85 0x58
Cleanup recv buffer before send: 0xff

The cleanup means there was a 0xff received after the last frame (valid) and before the send happened.

If you look at the received frame, it is nearly identical to the OK received frame:

RECV: 0xa 0x3 0x10 0x46 0x67 0x54 0x0 0x43 0xa0 0x27 
---> this one should probably not be there: 0xff
0xae 0x3d 0xcc 0xcc 0xcd 0x40 0x0 0x0 0x0 0x66
---> Missing the last byte of the CRC

the 0x10 means 16 data bytes, but due to the 0xff, the frame is not correct.

So there are not a pymodbus problem, but a USB or serial line problem, not much we can do about that.

RoGu777 commented 7 months ago

@janiversen thanks a lot for your analysis, I will then look what I can do to fix it