core: Modbus RTU does not seem to retry - Pymodbus: hub1: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 4 bytes (0 received)

The problem

Scan interval is 15 seconds (default). In a time frame from 30 min to 2 h, modbus sporadically misses single replies. Strangely, Modbus does not seem to retry and only requests again 15 seconds (scan interval) later, in the next run.

I have two devices (slave 1 and slave 2) in series. Tested with Waveshare USB FT232RL and now CH343G, but the result is the same.

What version of Home Assistant Core has the issue?

2023.2.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

homeassistant.components.modbus

Link to integration documentation on our website

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

Diagnostics information

log.txt

Example YAML snippet

modbus:
  - name: hub1
    type: serial
    baudrate: 9600
    bytesize: 8
    method: rtu
    parity: N
    port: /dev/ttyACM0
    stopbits: 1
    retry_on_empty: true
    retries: 10
    close_comm_on_error: false
    message_wait_milliseconds: 50
    delay: 1
    timeout: 1
    sensors: !include modbus_sensor.yaml
...
- name: sdm630_phase_1_power_w
  #name: SDM630 P1 WZ SZ EZ
  slave: 1
  address: 12
  input_type: input
  count: 2
  precision: 3
  scale: 1
  data_type: float32
  unit_of_measurement: W
  device_class: power
- name: sdm630_phase_2_power_w
  #name: SDM630 P2 AZ
  slave: 1
  address: 14
  input_type: input
  count: 2
  precision: 3
  scale: 1
  data_type: float32
  unit_of_measurement: W
  device_class: power
- name: sdm630_phase_3_power_w
  #name: SDM630 P3 KÜ HR
  slave: 1
  address: 16
  input_type: input
  count: 2
  precision: 3
  scale: 1
  data_type: float32
  unit_of_measurement: W
  device_class: power
- name: sdm630_total_system_power_w
  slave: 1
  address: 52
  input_type: input
  count: 2
  precision: 3
  scale: 1
  data_type: float32
  unit_of_measurement: W
  device_class: power
- name: sdm630_import_wh_since_last_reset
  slave: 1  
  address: 72
  input_type: input
  count: 2
  precision: 2
  data_type: float32
  unit_of_measurement: kWh
  device_class: energy
- name: sdm630_2_phase_1_power_w
  #name: SDM630 P1 WZ SZ EZ
  unique_id: sdm630_2_phase_1_power_w
  slave: 2
  address: 12
  input_type: input
  count: 2
  precision: 3
  scale: 1
  data_type: float32
  unit_of_measurement: W
  device_class: power

Anything in the logs that might be useful for us?

2023-02-26 19:03:11.609 DEBUG (SyncWorker_1) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2023-02-26 19:03:11.610 DEBUG (SyncWorker_1) [pymodbus.transaction] Running transaction 4825
2023-02-26 19:03:11.610 DEBUG (SyncWorker_1) [pymodbus.transaction] SEND: 0x1 0x4 0x0 0xc 0x0 0x2 0xb1 0xc8
2023-02-26 19:03:11.611 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Changing state to IDLE - Last Frame End - 1677434578.174977, Current Time stamp - 1677434591.610909
2023-02-26 19:03:11.611 DEBUG (SyncWorker_1) [pymodbus.client.base] New Transaction state "SENDING"
2023-02-26 19:03:11.613 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2023-02-26 19:03:11.667 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2023-02-26 19:03:11.668 DEBUG (SyncWorker_1) [pymodbus.transaction] RECV: 0x1 0x4 0x4 0x43 0xc9 0xaa 0x46 0xc1 0x6c
2023-02-26 19:03:11.668 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Getting Frame - 0x4 0x4 0x43 0xc9 0xaa 0x46
2023-02-26 19:03:11.668 DEBUG (SyncWorker_1) [pymodbus.factory] Factory Response[ReadInputRegistersResponse': 4]
2023-02-26 19:03:11.669 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Frame advanced, resetting header!!
2023-02-26 19:03:11.669 DEBUG (SyncWorker_1) [pymodbus.transaction] Adding transaction 1
2023-02-26 19:03:11.669 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Frame - [b'\x01\x04\x04C\xc9\xaaF\xc1l'] not ready
2023-02-26 19:03:11.669 DEBUG (SyncWorker_1) [pymodbus.transaction] Getting transaction 1
2023-02-26 19:03:11.670 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
2023-02-26 19:03:12.659 DEBUG (SyncWorker_9) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2023-02-26 19:03:12.659 DEBUG (SyncWorker_9) [pymodbus.transaction] Running transaction 4826
2023-02-26 19:03:12.659 DEBUG (SyncWorker_9) [pymodbus.transaction] SEND: 0x1 0x4 0x0 0xe 0x0 0x2 0x10 0x8
2023-02-26 19:03:12.660 DEBUG (SyncWorker_9) [pymodbus.framer.rtu_framer] Changing state to IDLE - Last Frame End - 1677434591.667448, Current Time stamp - 1677434592.660163
2023-02-26 19:03:12.660 DEBUG (SyncWorker_9) [pymodbus.client.base] New Transaction state "SENDING"
2023-02-26 19:03:12.661 DEBUG (SyncWorker_9) [pymodbus.transaction] Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2023-02-26 19:03:14.665 DEBUG (SyncWorker_9) [pymodbus.transaction] Transaction failed. (Modbus Error: [Invalid Message] No response received, expected at least 4 bytes (0 received)) 
2023-02-26 19:03:14.666 DEBUG (SyncWorker_9) [pymodbus.framer.rtu_framer] Frame - [b''] not ready
2023-02-26 19:03:14.666 DEBUG (SyncWorker_9) [pymodbus.transaction] Getting transaction 1
2023-02-26 19:03:14.666 DEBUG (SyncWorker_9) [pymodbus.transaction] Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
2023-02-26 19:03:14.666 ERROR (SyncWorker_9) [homeassistant.components.modbus.modbus] Pymodbus: hub1: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 4 bytes (0 received)
2023-02-26 19:03:14.736 DEBUG (SyncWorker_3) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2023-02-26 19:03:14.737 DEBUG (SyncWorker_3) [pymodbus.transaction] Running transaction 4827
2023-02-26 19:03:14.737 DEBUG (SyncWorker_3) [pymodbus.transaction] SEND: 0x1 0x4 0x0 0x10 0x0 0x2 0x70 0xe
2023-02-26 19:03:14.738 DEBUG (SyncWorker_3) [pymodbus.framer.rtu_framer] Changing state to IDLE - Last Frame End - 1677434594.665427, Current Time stamp - 1677434594.73794
2023-02-26 19:03:14.738 DEBUG (SyncWorker_3) [pymodbus.client.base] New Transaction state "SENDING"
2023-02-26 19:03:14.740 DEBUG (SyncWorker_3) [pymodbus.transaction] Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2023-02-26 19:03:14.792 DEBUG (SyncWorker_3) [pymodbus.transaction] Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2023-02-26 19:03:14.792 DEBUG (SyncWorker_3) [pymodbus.transaction] RECV: 0x1 0x4 0x4 0x42 0xe1 0xd9 0xf1 0x25 0xde
2023-02-26 19:03:14.792 DEBUG (SyncWorker_3) [pymodbus.transaction] Got response!!!
2023-02-26 19:03:14.793 DEBUG (SyncWorker_3) [pymodbus.framer.rtu_framer] Getting Frame - 0x4 0x4 0x42 0xe1 0xd9 0xf1
2023-02-26 19:03:14.793 DEBUG (SyncWorker_3) [pymodbus.factory] Factory Response[ReadInputRegistersResponse': 4]
2023-02-26 19:03:14.793 DEBUG (SyncWorker_3) [pymodbus.framer.rtu_framer] Frame advanced, resetting header!!
2023-02-26 19:03:14.794 DEBUG (SyncWorker_3) [pymodbus.transaction] Adding transaction 1
2023-02-26 19:03:14.794 DEBUG (SyncWorker_3) [pymodbus.framer.rtu_framer] Frame - [b'\x01\x04\x04B\xe1\xd9\xf1%\xde'] not ready
2023-02-26 19:03:14.794 DEBUG (SyncWorker_3) [pymodbus.transaction] Getting transaction 1
2023-02-26 19:03:14.794 DEBUG (SyncWorker_3) [pymodbus.transaction] Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"

... NEXT TRY FOR 0x1 0x4 0x0 0xe 0x0 0x2 0x10 0x8 ~ 15 SECS LATER ...

2023-02-26 19:03:27.660 DEBUG (SyncWorker_1) [pymodbus.transaction] Current transaction state - TRANSACTION_COMPLETE
2023-02-26 19:03:27.661 DEBUG (SyncWorker_1) [pymodbus.transaction] Running transaction 4832
2023-02-26 19:03:27.661 DEBUG (SyncWorker_1) [pymodbus.transaction] SEND: 0x1 0x4 0x0 0xe 0x0 0x2 0x10 0x8
2023-02-26 19:03:27.661 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Changing state to IDLE - Last Frame End - 1677434606.65926, Current Time stamp - 1677434607.661781
2023-02-26 19:03:27.662 DEBUG (SyncWorker_1) [pymodbus.client.base] New Transaction state "SENDING"
2023-02-26 19:03:27.664 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2023-02-26 19:03:27.716 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2023-02-26 19:03:27.717 DEBUG (SyncWorker_1) [pymodbus.transaction] RECV: 0x1 0x4 0x4 0x42 0x20 0x52 0x62 0x52 0xbf
2023-02-26 19:03:27.717 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Getting Frame - 0x4 0x4 0x42 0x20 0x52 0x62
2023-02-26 19:03:27.718 DEBUG (SyncWorker_1) [pymodbus.factory] Factory Response[ReadInputRegistersResponse': 4]
2023-02-26 19:03:27.718 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Frame advanced, resetting header!!
2023-02-26 19:03:27.718 DEBUG (SyncWorker_1) [pymodbus.transaction] Adding transaction 1
2023-02-26 19:03:27.718 DEBUG (SyncWorker_1) [pymodbus.framer.rtu_framer] Frame - [b'\x01\x04\x04B RbR\xbf'] not ready
2023-02-26 19:03:27.719 DEBUG (SyncWorker_1) [pymodbus.transaction] Getting transaction 1
2023-02-26 19:03:27.719 DEBUG (SyncWorker_1) [pymodbus.transaction] Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"

Additional information

graph

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Reactions: 2
  • Comments: 28 (9 by maintainers)

Most upvoted comments

Be patient, the fix will be included in pymodbus version 3.3

Hi, I see that the issue was solved in the pymodbus code, but the error is still happening in HA 2023.3.6 Was the solution already ported to HA? Thanks and Regards

Hi chx0003, thanyk you very much, your fix solved my issues completly!

I hope I’ve understood correctly what you meant.

Here is what I did: -Took modbus component folder from the last HA release (2023.5.4) -Placed that folder inside the custom_components folder of my HA host -Manually edited the file manifest.json from that folder adding the line: "version": "3.2.0", and changing the line "requirements": ["pymodbus==3.1.3"] to "requirements": ["pymodbus==3.2.0"] -Restarted HA

The result is that the issue reported here is gone and no other errors show for modbus! Plus, I believe that now I’m using v3.2.0 of PyModbus called from a custom component of HA. The only downside that I see with this solution is that the custom component won’t be updated automatically when you update the modbus component in HA.

After this test, could you update the manifest file included in the modbus component of HA to use at least v3.2.0 of PyModbus?

Thanks and Regards

Sure that would solve this problem, but reintroduce the problems the upgrade solved, so it is a non-starter.

I only upgrade the integration when there are real benefits to be hands, and not just because a new version is available. This attitude have caused som harder discussions with developers of non-core integrations.

What you could do is take the old version that works for you and install is as a custom_component (just add a version number in the manifest).

Hi, the version 3.3.0 of pymodbus was released. Could you integrate this version in HA to get rid of this error: https://pymodbus.readthedocs.io/en/latest/changelog.html#version-3-3-0 Thanks a lot!

That is a question you should ask in HA, but since that is also me I will answer.

Short answer is no, for a couple of reasons 3.2.0 are defunct, and the current release is 3.2.2. Version 3.3 is due in June, and that is planned to be integrated in HA. I am not sure it is worth the pain to bump library 2 times within a very short period of time

Hi, thanks to @cgernert and @janiversen it’s already fixed in pymodbus v3.2.0, is there plan to integrate this version in HA?