Binding Modbus 2.5.7. Stops working after unsuccessful read attempt

[rossko57]

It’s not about Winows hosting, my timing comment was about the horsepower of the host box. A Windows box, even an old laptop, will outperform the Pi that hosts most openHAB instances. And hence run into different internal timing issues.

[stfn82 (Stefan)]

I have experimented with polling values between 1 and 10 seconds. I noticed no difference.

[Kim_Andersen]

you still get the same communication issue?

It may be the same as one of my devices where I use a ethernet<>rs485 (modbus RTU) as mentioned, (except I dont loos connection to the poller). I just live with it.

[stfn82 (Stefan)]

@Kim_Andersen

you still get the same communication issue?

Yes, the issue stays the same.

@rossko57

The retry always seems to work, so it’s not serious. Most likely due to hammering the target with TCP disconnect/reconnect cycles. If you want to address this see -

TCP tuning If you are a user only of Modbus-RTU over serial, ignore this section. Modbus-TCP users read on… I wondered whether to make this a separate guide, as this is more about performance external to openHAB, but it is closely related. In Modbus-TCP, we use the standard TCP/IP communications protocol as a “carrier” for our Modbus flavoured data transactions. TCP in general is really peer-to-peer, but with Modbus our Master (openHAB) becomes a TCP Client, initiating communications with TCP…

I would recommend read the whole thing anyway if you expect to use a 250mS poll cycle ordinarily.

I’ve re-read that topic, changed reconnectAfterMillis to 60000 (tried this also previously) and added updateUnchangedValuesEveryMillis=60000 (haven’t tried this before).

I haven’t had a problem for 39 hours, so far looking good!

[ssalonen]

@stfn82 I presume that setting makes the problem more unlikely but still does not resolve the real root cause. I would appreciate if you can try out the following still, with the “bad” default settings, reconnecting the connection all the time.

@stfn82 @BHall

I would like to try one more thing, replacing one of the libraries used by the binding (pool2) to latest version with bug fixes.

Please find the instructions in this post : Modbus stops without any errors

[stfn82 (Stefan)]

openhab> bundle:list -s|grep pool
307 │ Resolved │  80 │ 2.8.1                   │ org.apache.commons.commons-pool2

openhab> bundle:list -s|grep modbus
303 │ Active   │  80 │ 2.5.8                   │ org.openhab.binding.modbus
306 │ Active   │  80 │ 2.5.8                   │ org.openhab.io.transport.modbus

An changed my thing back to:

Bridge modbus:tcp:SE7K [ host="10.0.0.34", port=502, id=1, timeBetweenTransactionsMillis=250, 
timeBetweenReconnectMillis=1000, connectMaxTries=3, reconnectAfterMillis=1000, connectTimeoutMillis=2500 /*, updateUnchangedValuesEveryMillis=60000*/ ] { 

Logging set to default.

Let’s see if we can break this too.

EDIT: Added per request @ssalonen

openhab> bundle:tree-show 306 |grep pool
+- org.apache.commons.commons-pool2 [307]

[ssalonen]

Can you also print out the bundle tree show command as well? Just to confirm the right version of pool2 is used by the binding

Edit : Yes, looks good!

[BHall (Brian Hall)]

@ssalonen,

I am sorry I have not yet done this requested procedure, have had some rather heavy family obligations the last few days that have occupied most of my time.

I can try to get this done tomorrow evening if you still need me to. I noticed that @stfn82 tried the procedure and it apparently did not help.

Has anything else surfaced that provides any clues?

Please advise how I should proceed.

Thanks!

[ssalonen]

@BHall I haven’t got any test results yet from @stfn82, no.

However, it did not work in the other thread (user jomojomo95). Modbus stops without any errors . So I assume that mere update of commons-pool2 to 2.8.1 is not enough.

I would like to move the discussion to there, to make it easier to communicate and to clarify that we are not discussing the original issue anymore of “2.5.7 stops working after unsuccessful read attempt”.

Check out the other thread for modbus-fix-hang version, once again attempt to fix the issue with another way.

[stfn82 (Stefan)]

The new pool doesn’t help. Binding still stops working multiple times a day.

[WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandler.ModbusPollerReadRequest@47edcab[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: SocketTimeoutException Read timed out [operation ID 19f23777-6ebc-4152-ac6e-a6f272162fd0]

I’ll move over to the other thread.

[rossko57]

@stfn82

SocketTimeoutException Read timed out

This is the binding working as it should. Your device failed to answer for some reason.

This is not “binding stops working”, not least because you said you get it multiple times a day (so it hasn’t stopped). Let’s not muddy up that investigation.

You already know you can avoid this with TCP timing changes, but have chosen to undo those changes. That’s fine, a while back you had the “silent stoppage” with 2.5.8 and are now trying to recreate the conditions you had then.

@stfn82

An changed my thing back to:

Bridge modbus:tcp:SE7K [ host="10.0.0.34", port=502, id=1, timeBetweenTransactionsMillis=250, 
timeBetweenReconnectMillis=1000, connectMaxTries=3, reconnectAfterMillis=1000, connectTimeoutMillis=2500 /*, updateUnchangedValuesEveryMillis=60000*/ ] { 

Comment - I hadn’t look closely at this before, please note that TCP Bridge Things don’t have an updateUnchangedValuesEveryMillis parameter. That belongs to data Things. (that won’t have done any harm)

I think I’d try it with timeBetweenTransactionsMillis=100 to speed things up a bit.
And of course a much bigger timeBetweenReconnectMillis when you’re ready to fix the retries…

[stfn82 (Stefan)]

@rossko57

This is not “binding stops working”, not least because you said you get it multiple times a day (so it hasn’t stopped). Let’s not muddy up that investigation.

OK let me rephrase that: My thing still stops working multiple times a day.

@rossko57

You already know you can avoid this with TCP timing changes, but have chosen to undo those changes.

This was per request, today I changed it back till I have time to test the latest modbus-fix-hang version.

@rossko57

I think I’d try it with timeBetweenTransactionsMillis=100 to speed things up a bit.
And of course a much bigger timeBetweenReconnectMillis when you’re ready to fix the retries…

I will also try this, but I already have experimented with many different settings. I didn’t notice any difference.

[ssalonen]

@stfn82

The new pool doesn’t help. Binding still stops working multiple times a day.

[WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandler.ModbusPollerReadRequest@47edcab[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: SocketTimeoutException Read timed out [operation ID 19f23777-6ebc-4152-ac6e-a6f272162fd0]

I’ll move over to the other thread.

@stfn82, looking forward to you testing the modbus-hang-fix as well. Let’s discuss that in the other thread.

But I do need to ask about the above error. I do not see anything unusual here… The problem we are trying to address in this thread is that nothing happens with the polling, no errors, no nothing. Polling simply stops. Did you experience this “stopping without errors”?

If you are getting tcp timeout issues, that is something different and something that would be best discussed in new thread. @rossko57 has created several guides to tune the binding for optimal performance with least errors.

[stfn82 (Stefan)]

@ssalonen

But I do need to ask about the above error. I do not see anything unusual here… The problem we are trying to address in this thread is that nothing happens with the polling, no errors, no nothing. Polling simply stops. Did you experience this “stopping without errors”?

I’m not sure. I was on mobile this morning, so couldn’t investigate the logs very easy. I grepped on “error” and this come up around the time when I no longer received data from my thing. But this error also shows up quite often when the binding / my thing are working. So probably unrelated to the polling no longer working. Normally it would just stop without an error or warning.

I don’t have much free time this week, next 2 week I have plenty of time. I can try your updated version this weekend.

I did a quick check now I’m on my desktop:

Last error:

2020-09-08 00:06:28.617 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandler.ModbusPollerReadRequest@47edcab[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=69,length=50,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: SocketTimeoutException Read timed out [operation ID 19f23777-6ebc-4152-ac6e-a6f272162fd0]

Last item update:

2020-09-08 00:07:00.106 [vent.ItemStateChangedEvent] - SE7KACFrequency changed from 49.94 Hz to 49.95 Hz

The item was updated after the last error, indicating that the binding recovered from the error and continues working. And thus later stops working without displaying an error.

[ssalonen]

Clear. Thanks for checking, just wanted to confirm.

Appreciate the help with the testing

[HenMus]

SMA error 11.59 smal.pcapng.txt (69.9 KB) I believe I have the same problem. I’m using OH2 with binding-modbus - 2.5.2. I looked at the protocol (mirror port on my switch) and see many problems and in attached packet capture you see around 11.59 hours that the data exchange even stops and only re-transmission continue. Remove the .txt extension.
I use the following configuration
Bridge modbus:tcp:tripower “SMA Sunny Tripower 5000TL-20” @ “Zolder” [ host=“192.168.100.85”, port=502, id=3, connectMaxTries=3, reconnectAfterMillis=60000, connectTimeoutMillis=3000] {

Bridge poller SMA_Poller_Totaal "SMA_Poller_Totaal" [ start=30531, length=10, refresh=5000, type="holding" ] { 

    Thing data SMA_Totaal "SMA_Input_Totaal" [ readStart="30531", readValueType="uint32", readTransform="JS(divide1000.js)"]  

    Thing data SMA_Vandaag "SMA_Input_Vandaag" [ readStart="30535", readValueType="uint32", readTransform="JS(smalimit.js)"] 

} 

Bridge poller SMA_Poller_Huidig "SMA_Poller_Huidig" [ start=30775, length=8, refresh=5000, type="holding" ] {

    Thing data SMA_Huidig "SMA_Input_Huidig" [ readStart="30775", readValueType="int32", readTransform="JS(smalimit.js)"]   

}

}
In the logfile I see
2020-09-12 11:17:00.916 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 2/3 error: connect timed out. Connection TCPMasterConnection@6060e114[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:03.979 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 3/3 error: connect timed out. Connection TCPMasterConnection@6060e114[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:03.979 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 3, throwing last error: connect timed out. Connection TCPMasterConnection@6060e114[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:03.980 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@6060e114[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]: connect timed out

2020-09-12 11:17:03.980 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502] – aborting request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@408c60ad[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30531,length=10,maxTries=3] [operation ID e43abc95-d803-4a0a-92ad-ef1462dbe5ae]

2020-09-12 11:17:03.981 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:tripower:SMA_Poller_Totaal:SMA_Totaal ‘SMA_Input_Totaal’ had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502])

2020-09-12 11:17:03.981 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:tripower:SMA_Poller_Totaal:SMA_Vandaag ‘SMA_Input_Vandaag’ had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502])

2020-09-12 11:17:06.983 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/3 error: connect timed out. Connection TCPMasterConnection@592f47e9[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:10.047 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 2/3 error: connect timed out. Connection TCPMasterConnection@592f47e9[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:13.111 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 3/3 error: connect timed out. Connection TCPMasterConnection@592f47e9[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:13.111 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 3, throwing last error: connect timed out. Connection TCPMasterConnection@592f47e9[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:13.112 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@592f47e9[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]: connect timed out

2020-09-12 11:17:13.112 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502] – aborting request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@11ded93c[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=8,maxTries=3] [operation ID 6d4254f9-2c01-4e2d-98db-6285714ea7a2]

2020-09-12 11:17:13.113 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:tripower:SMA_Poller_Huidig:SMA_Huidig ‘SMA_Input_Huidig’ had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502])

2020-09-12 11:17:16.116 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/3 error: connect timed out. Connection TCPMasterConnection@782c38b0[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:19.178 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 2/3 error: connect timed out. Connection TCPMasterConnection@782c38b0[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:22.242 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 3/3 error: connect timed out. Connection TCPMasterConnection@782c38b0[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2020-09-12 11:17:22.243 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 3, throwing last error: connect timed out. Connection TCPMasterConnection@782c38b0[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@20a39fe2[address=192.168.100.85,port=502]

2

[rossko57]

@HenMus

I believe I have the same problem.

I don’t see why. To all appearances, openHAB is trying to communicate with your device but it is not responding. Seems to be the opposite of the symptoms here.

[HenMus]

The log file is a result of the protocol failures. I’m almost sure that is the root cause.

[rossko57]

I’m not sure what you want to happen next.

The binding is throwing errors because your device is not responding as expected. (From what I can see, not responding at all)

The binding will continue to attempt communication unless you tell it different.
This is unrelated to the binding stopping polling unannounced, the topic of this thread.

There is an updated binding version available for the stoppage problem, which of course you can try if you think you have the ‘same problem’.
I don’t think that will help at all.

I cannot view your image file, would you be able to post text version in code fences?

[Kim_Andersen]

@HenMus

Bridge modbus:tcp:tripower “SMA Sunny Tripower 5000TL-20” @ “Zolder” [ host=“192.168.100.85”, port=502, id=3, connectMaxTries=3, reconnectAfterMillis=60000, connectTimeoutMillis=3000] {

I have a SMA Tripower 6000TL-20. I dont have the same issues.