Race condition in modbus_controller when quickly sending on/off switch command

[vanackej]

The problem

When quickly sending 2 consecutive commands to a modbus device (in my situation, an 8ch modbus relay, but the issue is generic I think), the modbus_controller first looks in the command queue if another command is already queued for this device. If any existing command is found, it's payload is updated with the payload of the new command, and the new command is ignored (here in source code)

If the first command has not yet been sent, this can be ok. But when it happens when the first command has already been sent, the payload of the second command replaces the one from the first command, but is never sent. This happens because the last sent command stays on the command_queue while waiting for a response. For exemple, the first ON command is sent, but the OFF command is ignored. In Home assistant, the switch state appears as OFF, but the OFF command have never been actually sent.

Potential fix : always remove the current command from the command_queue when sending the command, and store it in another variable for response processing. On send error, the command could be placed on the command_queue again. Doing so, we won't discard the second OFF command when the ON command has been sent and is stilll waiting for a reply.

A side effect of this fix would be that it would allow other commands to be executed in between attempts to send the same command again in case of a failure. This could maybe be good in case of a failed device that would slow down every other command to other devices., don't you think ?

Which version of ESPHome has the issue?

2022.11.4

What type of installation are you using?

Home Assistant Add-on

Which version of Home Assistant has the issue?

2022.11.5

What platform are you using?

ESP32

Board

No response

Component causing the issue

modbus_controller

Example YAML snippet

modbus:
  id: modbus1 
  send_wait_time: 250ms

modbus_controller:
  - id: relay_switch
    address: 0xFF
    modbus_id: modbus1
    update_interval: 120s
switch:
 - platform: modbus_controller
    id: relay_1
    name: "Relais 1"
    modbus_controller_id: relay_switch
    register_type: coil
    address: 0
    offset: 0

Anything in the logs that might be useful for us?

[18:32:37][D][switch:013]: 'Relais 1' Turning ON.
[18:32:37][V][modbus_controller.switch:072]: write_state 'Relais 1': new value = ON type = 1 address = 0 offset = 0
[18:32:37][D][switch:037]: 'Relais 1': Sending state ON
[18:32:37][V][json:031]: Attempting to allocate 512 bytes for JSON serialization
[18:32:37][V][json:051]: Size after shrink 72 bytes
[18:32:37][V][modbus_controller:036]: Sending next modbus command to device 255 register 0x00 count 1
[18:32:37][V][modbus:194]: Modbus write: FF.05.00.00.FF.00.99.E4 (8)
[18:32:37][V][modbus_controller:486]: Command sent 5 0x0 1
[18:32:37][D][switch:017]: 'Relais 1' Turning OFF.
[18:32:37][V][modbus_controller.switch:072]: write_state 'Relais 1': new value = OFF type = 1 address = 0 offset = 0
[18:32:37][W][modbus_controller:113]: Duplicate modbus command found: type=0x1 address=0 count=1
[18:32:37][D][switch:037]: 'Relais 1': Sending state OFF
[18:32:37][V][json:031]: Attempting to allocate 512 bytes for JSON serialization
[18:32:37][V][json:051]: Size after shrink 72 bytes
[18:32:37][D][uart_debug:114]: >>> FF:05:00:00:FF:00:99:E4
[18:32:37][V][modbus:042]: Modbus received Byte  255 (0Xff)
[18:32:37][V][modbus:042]: Modbus received Byte  5 (0X5)
[18:32:37][V][modbus:042]: Modbus received Byte  0 (0X0)
[18:32:37][V][modbus:042]: Modbus received Byte  0 (0X0)
[18:32:37][V][modbus:042]: Modbus received Byte  255 (0Xff)
[18:32:37][V][modbus:042]: Modbus received Byte  0 (0X0)
[18:32:37][V][modbus:042]: Modbus received Byte  153 (0X99)
[18:32:37][V][modbus:042]: Modbus received Byte  228 (0Xe4)
[18:32:37][V][modbus_controller:055]: Modbus response queued
[18:32:37][V][component:200]: Component modbus took a long time for an operation (0.05 s).
[18:32:37][V][component:201]: Components should block for at most 20-30ms.
[18:32:37][V][modbus_controller:063]: Process modbus response for address 0x0 size: 4
[18:32:37][V][modbus_controller:308]: Command ACK 0x0 255 
[18:32:37][D][uart_debug:114]: <<< FF:05:00:00:FF:00:99:E4

Additional information

No response

[nagyrobi]

In Home assistant, the switch state appears as OFF, but the OFF command have never been actually sent.

I am able to reproduce this behavior with my 24ch modbus relay card.

[nagyrobi]

@martgras @ssieb

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[vanackej]

Keep open, the problem is confirmed and has no fix yet

[0x3333]

I don't see why this is the default behavior, if there are multiple commands to the same node, it should just issue, eventually log, but it should not just discard the command.

[0x3333]

@martgras Do you think that adding a "Allow Duplicate Cmd" to the ModbusController would be an option?

I can't have these commands discarded.

Ps.: I'm able to implement an PR for this.

[nagyrobi]

I think something like allow_duplicate_commands would be useful. There are indeed such cases.