modbus component fails to deal with TCP timeout

[frodef]

The problem

I have a TCP modbus device that does simple polling of some modbus registers. This works quite well, until once every few hours the modbus interface doesn't respond to a request on time (for whatever reason). The problem is not the timed out request, but the modbus stack seems to enter a state where it does not recover from the failure: Every subsequent request will also fail, even though the modbus interface itself continues to operate as it should. It appears that in fact no more requests are actually being sent to the modbus interface.

When this bug strikes, the modbus entities no longer update, and one debug log message is emitted on every update. There is no proper error signalled, it seems. Debug message:

2023-08-29 08:55:58.170 DEBUG (SyncWorker_1) [homeassistant.components.modbus.modbus] Pymodbus: hub1: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(192.168.1.186:8899)]

If I restart the HA process, or use other software to interact with the modbus interface, it works perfectly. Also, tcpdump confirms that once the bug strikes, no more request are sent over the wire to the modbus interface.

I have tried to debug the problem, which was a bit difficult because it can take many hours for the error condition to happen to trigger the bug. However, I can artificially inject an error that I believe triggers the bug by modifying pymodbus/client/tcp.py method recv around line 209 to the following:

    self.foo -= 1
    while recv_size > 0:
        try:
            wait = [self.socket]
            if self.foo<=0:
                wait = []
                self.foo = 1000
            ready = select.select(wait, [], [], end - time_)

Before this, e.g. in the constructor, self.foo is initialized to 10 or so. The idea is to have HA settle, then force a single "no response" timeout from select. Obviously the modbus request where this fault injection occurs will fail. The bug however is that all subsequent requests also fail.

As far as I can tell, what happens is that the TCP socket is closed in pymodbus/transaction.py:251 and is then never even attempted to be opened again. I don't understand if (triggering) re-opening the socket should happen from inside pymodbus or if it's the ha modbus component that should act on this.

What version of Home Assistant Core has the issue?

core-2023.9.0.dev0

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

modbus

Link to integration documentation on our website

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

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2023-08-29 08:55:58.170 DEBUG (SyncWorker_1) [homeassistant.components.modbus.modbus] Pymodbus: hub1: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(192.168.1.186:8899)]

Additional information

No response

[home-assistant]

Hey there @adamchengtkc, @janiversen, @vzahradnik, mind taking a look at this issue as it has been labeled with an integration (modbus) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of modbus can trigger bot actions by commenting:

• @home-assistant close Closes the issue.
• @home-assistant rename Awesome new title Renames the issue.
• @home-assistant reopen Reopen the issue.
• @home-assistant unassign modbus Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

---

modbus documentation
modbus source
_{^{(message by IssueLinks)}}

[janiversen]

Please add a debug log as pr modbus integration documentation.

It looks as if:

• there is a timeout, for whatever reason
• modbus integration disconnects (or is disconnected due to a close in your device)
• modbus integration should try to reconnect with an ascending interval. You should have messages to that fact in the log, but it depends on your configuration, which you have not added.

Your patch for pymodbus might be correct, but you should submit a PR to https://github.com/pymodbus-dev/pymodbus if you want that changed. Pymodbus will release v3.5.0 in the weekend or beginning next week, this will subsequently by used by the modbus integration so time is of essence.

[frodef]

There is nothing else in the debug log except the line I have included, plus the original error. However I'll include a full log, too. There is no message or any evidence of the system trying to reconnect, as far as I can tell. Also I have tried to trace/instrument the code extensively, and I have not found or understood where the reconnect is supposed to occur.

The code I provided is only a (very quick and dirty) way to reproduce the error condition. It is by no means intended to fix or solve the actual problem, and therefore a PR would be inappropriate, I believe.

The attached log-file is HA running with the fault injection code I mentioned. I stopped HA after 6 "Failed to connect" occurrences, but this would have gone on forever. The log is the same as what I have seen several times "in the wild", except it can take many hours to occur.

home-assistant.log

[janiversen]

I did not ask for a full log, but a debug log. Debug is not activated pr default for modbus and pymodbus.

I do not understand why you say "There is no message or any evidence of the system trying to reconnect", the log have a number of "connect failed" which is reconnect working. Seems something is blocking the reconnect, but I cannot tell you what, we have seen issues with the HA security (where the network was not permitted) and more frequently that the device rejects a new connection.

[frodef]

Sorry, I forgot to enable pymodbus debug.

About my statement "There is no message or any evidence of the system trying to reconnect": The "Failed to connect" exception is emitted when the code sees that there is no open socket (it was closed as I explained in the first message). This happens in pymodbus/client/base.py:183 method ModbusBaseClient.execute. It looks to me that the code/logic there assumes there has been a (re)connection attempt. But there hasn't, as far as I can tell. Consequently, the ha entities are never again updated after this fault happens once.

home-assistant.log

[janiversen]

This is the Home assistant Core project, not the pymodbus project, again if you think there are issues in pymodbus then please submit a PR there.

There are reconnect attempts:

2023-08-29 10:43:26.613 DEBUG (SyncWorker_2) [homeassistant.components.modbus.modbus] Pymodbus: hub1: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(192.168.1.186:8899)]

and 4 seconds later:

2023-08-29 10:43:26.613 DEBUG (SyncWorker_2) [homeassistant.components.modbus.modbus] Pymodbus: hub1: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(192.168.1.186:8899)]

etc.

there is a couple of strange entries:

2023-08-29 10:43:25.619 DEBUG (MainThread) [homeassistant.components.modbus.sensor] Manually updated Kurs data

which could be cause of the reconnect attempt.

I can only base this on theory, because this depends on how you have configured the tcp connection, which you have decided not to show. There are a number of parameters that affect reconnect.

Have you tried to restart the integration ?

[frodef]

Like I said, I don't understand the code well enough to understand if this is a problem with pymodbus and/or ha/components/modbus. I'd be happy to submit a PR, but alas, again, I don't understand how to fix the problem properly.

I just tried to explain in some detail that there are in fact no actual reconnection attempts, and the exact nature of those log entries you quote. Again, with the caveat that I struggle to follow/understand the code.

The "strange entries" are emitted by ha/helpers/update_cooridnator.py:411 DataUpdateCoordinator.async_set_updated_data

I have extensively instrumented and tried to trace the modbus code. I have "restarted the integration" countless times.

Here is my modbus config:

• name: hub1
  type: tcp
  host: 192.168.1.186
  port: 8899
  sensors:
  • name: Kurs
    unit_of_measurement: W
    scan_interval: 4
    slave: 1
    scale: 0.480
    address: 0x08
    precision: 0
    input_type: holding
    data_type: uint16
    count: 1
    unique_id: sv30ckurs
    slave_count: 15

[janiversen]

There you see, how could I know you use "slave_count", had you shown that in the first place as requested, we had saved a lot of words.

This means the reconnect attempts you have in the log are real reconnect attempts!

There are a couple of parameters in the network configuration that might help solve your problem, please see the modbus integration documentation.

You have tried to restart the integration countless times, but how about reporting just once, if it had an effect, meaning it became operational again.

[janiversen]

and while I am add it, the sensor configuration is invalid please see "parameter usage", however with .4 it still passes.

This has no effect on the reconnect issue.

[janiversen]

Notice: No bug in HA, working as expected!

It might be a problem/bug in the sync client of pymodbus or elsewhere blocking the reconnect from successfully completing.

Put on hold until pymodbus is bumped and the integration is changed to use async client, which is all planned.

[frodef]

Thank you for looking into this. If this is a pymodbus issue and not HA core, and there's a new pymodbus version on the way, I'll be happy to wait for that.

FWIW I saw no difference wrt. this issue when I removed the slave_count from my modbus config. (I also removed the count entry which was there for no reason, made no difference.)