Modbus stops without any errors

After 2 days without any stops (idk why) I had a stop today again but sadly I could not log it with trace as I did the karaf trace setting first and afterwards changed the logs settings, this must have stop the trace logging I guess. :frowning:
I changed the logging to trace again and see the traces coming in.

FYI this are the traces of the stopped behavior, it still tries to poll but without any Item changes:

2020-09-05 13:10:33.134 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:33.137 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9650810. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:33.140 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:33.143 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

2020-09-05 13:10:43.146 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:43.150 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9660822. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:43.154 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:43.159 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

2020-09-05 13:10:53.163 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:53.168 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9670840. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:53.171 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:53.174 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

I’ll restart the binding and will report as I have a stop again.

@jomojomo95, no it’s not polling. The regular poll monitor log messages are actually just diagnostics information for troubelshooting.

@Kim_Andersen I assume no log with the trace logging? Based on user reports it seems the issue is less likely when there is verbose logging enabled…indicating a timing issue.

@jomojomo95 @Kim_Andersen ,

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

  1. Uninstall modbus binding, using Paper UI
  2. Confirm uninstallation using bundle:list -s |grep modbus, no bundles should be installed
  3. Download modbus258.zip.pdf (309.9 KB) and rename modbus258.zip.pdfas modbus258.zip
  4. Unzip
  5. Find 2.5.8 jar files and copy them under addons
  6. Check the logs, you will probably have error there
SNIP
         Unresolved requirement: Import-Package: gnu.io; version="[3.12.0,6.0.0)"
SNIP
  1. gnu.io dependency is missing. Install it by feature:install openhab-transport-serial, and restart the bundles using bundle:restart
openhab> feature:install openhab-transport-serial
openhab> bundle:list -s |grep modbus
203 │ Installed │  80 │ 2.5.8      │ org.openhab.io.transport.modbus
205 │ Installed │  80 │ 2.5.8      │ org.openhab.binding.modbus
openhab> bundle:restart 203 205  # Find correct IDs above
  1. Check the logs (log:tail), you will probably have error there, slightly different this time:
	Unable to start bundle 203: Could not resolve module: org.openhab.io.transport.modbus [203]
  Unresolved requirement: Import-Package: org.apache.commons.pool2; version="[2.4.0,3.0.0)"
...
  1. org.apache.commons.pool2 dependency is missing. Install it by bundle:install, and restart the bundles using bundle:restart. This time we install the latest version available, 2.8.1. This is newer than the version provided by default openHAB 2.5.8 installation

NOTE If you do not see the error regarding org.apache.commons.pool2, do not continue

openhab>bundle:install https://repo1.maven.org/maven2/org/apache/commons/commons-pool2/2.8.1/commons-pool2-2.8.1.jar
openhab> bundle:list -s |grep modbus
203 │ Installed │  80 │ 2.5.8      │ org.openhab.io.transport.modbus
205 │ Installed │  80 │ 2.5.8      │ org.openhab.binding.modbus
openhab> bundle:restart 203 205  # Find correct IDs above
  1. Bundles should be now active, with no errors in logs
openhab> bundle:list -s |grep modbus
203 │ Active   │  80 │ 2.5.8      │ org.openhab.io.transport.modbus
205 │ Active   │  80 │ 2.5.8      │ org.openhab.binding.modbus
openhab> log:tail
...
08:16:58.685 [INFO ] [ort.modbus.internal.ModbusManagerImpl] - Modbus manager activated
08:16:58.946 [INFO ] [ort.modbus.internal.ModbusManagerImpl] - Modbus manager activated
  1. Finally confirm the apache pool2 is the correct version, 2.8.1
openhab> bundle:tree-show 203 |grep pool # replace 203 with id of transport bundle (see above)
+- org.apache.commons.commons-pool2 [278]
openhab> bundle:list -s|grep pool
278 │ Resolved │  80 │ 2.8.1                   │ org.apache.commons.commons-pool2

Check that you have the same number (278) above outputted by both commands above. This means that modbus binding is using really the version 2.8.1 of pool2 library.

  1. Installation successfull

Ok, did as described step by step.
Now have the modbus jars active and pool2 resolved.
I hadn’t had to install gnu.io but I guess that’s ok.

@ssalonen should I stop the trace logging to force it faster or just let it run?

1 Like

Sounds good. Remove the trace logging please, hopefully it is more likely to get the issue then

You´re right. everything is working fine since I´d enabled the trace log…
I will not have time to give your suggest a try untill late tonight or tomorrow. But I will give it a try for sure.

1 Like

I got two stops since the change.
First one was just after 1 hour second around 11 hours.
So it seems no fix with the new pool2 version.

Ok that’s a shame to hear :grimacing:

Would you please run the threads commands when it is stuck?

Yet another possible fix

Install the binding manually, with pool 2.8.1, per the instructions in this post. Use the jar files from this zip:
modbus-fix-hang-reupload.zip.pdf (309.0 KB)

Successful installation should look like (check the date part after 2.5.9....)

openhab> bundle:list -s|grep '(modbus|pool)'; bundle:tree-show org.openhab.io.transport.modbus|grep pool2
256 │ Active   │  80 │ 2.5.9.202009100355      │ org.openhab.io.transport.modbus
257 │ Active   │  80 │ 2.5.9.202009100357      │ org.openhab.binding.modbus
266 │ Resolved │  80 │ 2.8.1                   │ org.apache.commons.commons-pool2
+- org.apache.commons.commons-pool2 [266]

2 Likes

Can you upload modbus-fix-hang.zip again? jar files contain only text of .jar file locations…
I have the same issue since I configured my inverter (SE4K) - it works for a few hours then suddenly stops - no matching errors in log files.

After about two days without any interupts I just got an stop again.
Here is the threads output: threads.txt (77.0 KB)

I will try the new possible fix tomorrow.
As said by @pewu78 the .jar Files you uploaded are only 1kb, I guess the compile failed.

1 Like

Thanks @pewu78 @jomojomo95. Reuploaded above.

Thanks. Got it up running as instructed together with org.openhab.binding.modbus.sunspec-2.5.8.jar, will see how it works.

Hi @ssalonen sorry for beeing away… I had some personal issues here I had to deal with first… Modbus has been running stable ever since I started the trace logging.

Anyway, I´m ready to test now. Just one question.
When using Zigbee og Zwave, I assume #8 should not become a problem. As far as I recall, both Zigbee and Zwave uses the transport serial, right?

You are probably correct indeed. If you do not get error on “gnu.io” then it’s fine.

Regarding trace logging: Yes… It seems that the problem does not manifest with the trace logging enabled. This is a bit of luck and probabilities… I presume the few extra milliseconds that go into logging help to sidestep the bug.

In order to test the new possible fix, I would like you to remove the trace logging, to make it more likely to encounter the issue if it is still present. Our target is of course have the system working with all logging levels :slight_smile:

Hi any update on the stability with the fix?

We are bit rushed to get this into 2.5.9 release, so all test results are most appreciated :slightly_smiling_face:

I have it running since yesterday fine - it’s the first time it worked for so long (overnight), so it’s a good sign. :+1:
My only issue is with status item (string) - it’s not obtained for some reason…

1 Like

Sorry haven’t had any time yesterday, just switched the modbus bindings to 2.5.9.
Will give feedback as I have results.

I hope I can try the latest update tonight, have had some other stuff going on. Maybe this will be “the fix”.

1 Like

Have it up running for a few hours… Still no issue.
Anyway… For some reason I had to install the transport serial, even though I have Zwave and Zigbee running as well… Pretty weird!

1 Like

For me it’s still working, so I’m eager to say it’s fixed. Thank you.

1 Like