Problem with modbus binding with dynamic on/off

Add-ons Bindings
, ,
12

I have had nothing but several issues with USB ports on my Rpi´s. With or without Exstra_Java_opts, it works like the wind blows… Everytime I reboot my Rpi, I can be pretty sure to have somekind of issues with the devices connected to the USB ports. This is a stupid Linux “feature”.
But I have had no issues when things are up an running. Then the modbus (RS485) runs very stable.

I have bought a tcp modbus adaptor for the very same reason. Unfortunatly I have no had the time to install and test it yet. I bought a Waveshare RS485 to ethernet:
https://www.amazon.de/gp/product/B07S2K41MS/ref=ppx_yo_dt_b_asin_title_o01_s01?ie=UTF8&psc=1

13

There is more to this than just a timeout; even if the binding did release the port … who has got hold of it now, to prevent simple re-acquisition?

14

I cannot reproduce this with 2.5.1 release :frowning:, at least not on linux.

What I tried (for the record)

  1. Modified start.sh to support my serial ports:
...
# Add gnu.io.rxtx.SerialPorts property for proper serial port detection
export JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/pts/8:/dev/pts/9"
exec "${RUNTIME}/bin/karaf" "${@}"
  1. Created things: things/manual.things, connect to serial device /dev/pts/9:
Bridge modbus:serial:serial9 [ port="/dev/pts/9", id=1 ] {
    Bridge poller pollerSerial [ start=0, length=6, refresh=0, type="holding" ] {
        Thing data holdingSerial [ readStart="1", readValueType="int16" ]
    } 
}
  1. Start artificial “null modem” serial port using tty0tty (since I do not have real serial devices). This creates two artificial serial devices which are connected to each other – writing data to other will be readable from other end.
$ ./pts/tty0tty                                                                                                                                                        master
(/dev/pts/8) <=> (/dev/pts/9)
  1. Start modbus slave, listening on serial port /dev/pts/8 ("linked to /dev/pts/9):
sudo ./diagslave -m rtu /dev/pts/8
  1. Start openhab using start.sh
  2. Install modbus binding 2.5.1 using PaperUI
  3. Using PaperUI, link holdingSerial thing’s number channel to new item called SerialHoldingNumber
  4. Trigger refresh of data using curl against openHAB HTTP API: curl -v -H "Content-Type: text/plain" -H "Accept: application/json" -XPOST -d REFRESH http://localhost:8080/rest/items/SerialHoldingNumber

curl command is executed successfully with no errors in openHAB logs. In addition, I can see the modbus request registered by the modbus slave (diagslave):

Slave   1: readHoldingRegisters from 1, 6 references

Even though I rename things file, edit it, etc. I do not get “Port In Use” error messages.

The release version 2.5.1 does suffer from issue 6876 which means that changes are not picked properly always in things file. Editing the file couple of times will make the changes propagate properly in openHAB. Alternatively one can “force” things to be picked up by disabling and enabling things from UI.

Could it be that something else is taking the port in use (as speculated by @rossko57 above) ? One can check who is using the port using lsof command:

$ sudo lsof /dev/pts/{8,9}
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs
      Output information may be incomplete.
lsof: WARNING: can't stat() fuse file system /run/user/1000/doc
      Output information may be incomplete.
COMMAND     PID   USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
java      74492 salski   32u   CHR  136,9      0t0   12 /dev/pts/9
diagslave 77513   root    3u   CHR  136,8      0t0   11 /dev/pts/8

Above one can see that java process is holding /dev/pts/9 while diagslave is holding /dev/pts8 – this is expected.

@EjvindHald, could you try to run the lsof command when you get the PortInUseException?

1 Like
15

Thank you very much for effort to try to reproduce the problem.

Compare to my setup there is one important difference: I also physically remove the power from the modbus device (that is the whole idea).

The most stable setup I have so far is to disable the poller, wait some seconds and then power off the modbus device. If I just power off the device without the previous steps, I get very often PortInUse error.

Could it be that powering off a device can lead to a not graceful ending of a thread? I remember I had a java exception error in the log a couple of times immediate following a turn off operation, where I got PortInUse error afterwards.

I will check the log next time I get the error as you suggest.

16

My initial reaction is “so what” - it makes no difference.
Except … if you have a really weird RS485 adaptor at your host that fails to apply bias or termination to the line (and it was relying on the remote device for that) and so gets garbage faux data.
There’s no evidence of that, nor would I expect garbage data to give those symptoms anyway. It’s really unlikely.

Sure. Badly designed setups can “squawk” garbage data as they die.
Again, there is no evidence of that happening nor reason to think it could do anything nastier than tie up a poll for a timeout period, until it logged an error.

None of that should affect the Serial Bridg Thing or its “hold” on the port.

It’s going to be helpful to see that.

The binding should simple discard unsolicited data (because Modbus is strictly Master query, Slave respond). I suppose there is scope for funny business if unsolicited data is also corrupt.

We should perhaps remember there is java between “us” and the serial line too. If that mishandles a squawk of garbage it might release our reservation of the port.
Which still leaves the mystery of who grabs it then to make it “busy”?

1 Like
17

Also today I have been trying to fix the problem. And I got some log entries, which might be interesting, and they are shown below. However, I have not found deterministic way to reproduce the problem.

Snippet from the log:

2020-02-29 17:58:01.031 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error invalidating connection in pool for endpoint ModbusSerialSlaveEndpoint@788895a5[portName=/dev/ttyUSB5]. Error was: java.lang.IllegalMonitorStateException null
java.lang.IllegalMonitorStateException: null
at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryRelease(ReentrantReadWriteLock.java:371) ~[?:1.8.0_242]
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261) ~[?:1.8.0_242]
at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.unlock(ReentrantReadWriteLock.java:1131) ~[?:1.8.0_242]
at gnu.io.RXTXPort.close(RXTXPort.java:1101) ~[?:?]
at net.wimpi.modbus.io.ModbusSerialTransport.close(ModbusSerialTransport.java:97) ~[?:?]
at net.wimpi.modbus.io.ModbusRTUTransport.close(ModbusRTUTransport.java:202) ~[?:?]
at net.wimpi.modbus.net.SerialConnection.close(SerialConnection.java:262) ~[?:?]
at net.wimpi.modbus.net.SerialConnection.resetConnection(SerialConnection.java:331) ~[?:?]
at org.openhab.io.transport.modbus.internal.pooling.ModbusSlaveConnectionFactoryImpl.destroyObject(ModbusSlaveConnectionFactoryImpl.java:152) ~[?:?]
at org.openhab.io.transport.modbus.internal.pooling.ModbusSlaveConnectionFactoryImpl.destroyObject(ModbusSlaveConnectionFactoryImpl.java:1) ~[?:?]
at org.apache.commons.pool2.impl.GenericKeyedObjectPool.destroy(GenericKeyedObjectPool.java:1104) ~[?:?]
at org.apache.commons.pool2.impl.GenericKeyedObjectPool.invalidateObject(GenericKeyedObjectPool.java:585) ~[?:?]
at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.lambda$1(ModbusManagerImpl.java:365) ~[?:?]
at java.util.Optional.ifPresent(Optional.java:159) ~[?:1.8.0_242]
at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.invalidate(ModbusManagerImpl.java:363) ~[?:?]
at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.lambda$9(ModbusManagerImpl.java:609) ~[?:?]
at org.openhab.io.transport.modbus.internal.SimpleStopWatch.timeConsumer(SimpleStopWatch.java:169) ~[?:?]
at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.executeOperation(ModbusManagerImpl.java:609) ~[?:?]
at org.openhab.io.transport.modbus.internal.ModbusManagerImpl.lambda$15(ModbusManagerImpl.java:723) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_242]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_242]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_242]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_242]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_242]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_242]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_242]
^C
root@ejvind-Latitude-E5550:/var/log/openhab2# sudo lsof /dev/ttyUSB5
lsof: WARNING: can’t stat() fuse.gvfsd-fuse file system /run/user/1000/gvfs
Output information may be incomplete.
lsof: WARNING: can’t stat() fuse file system /run/user/1000/doc
Output information may be incomplete.
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 8096 openhab 93u CHR 188,0 0t0 336 /dev/ttyUSB0
root@ejvind-Latitude-E5550:/var/log/openhab2#

—and shortly after:
2020-02-29 18:01:29.846 [ERROR] [et.wimpi.modbus.net.SerialConnection] - open port failed: gnu.io.PortInUseException: Modbus Serial Master
2020-02-29 18:01:29.847 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: open port failed: Modbus Serial Master. Connection SerialConnection@7424e5d9[portName=/dev/ttyUSB5,port=]. Endpoint ModbusSerialSlaveEndpoint@788895a5[portName=/dev/ttyUSB5]

1 Like
18

@ssalonen may make something of it, but you’d better describe the circumstance. Powering off your target device during normal operation?
That fuse.gvfsd-fuse stuff looks relevant to port handling

I guess you’ve revealed your host is a laptop (not the usual Pi) :smiley:

19

Here is another variant I just received which I am sure has popped up earlier:

2020-02-29 18:39:12.525 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Unregistering regular poll task BasicPollTaskImpl@531d1e75[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@195c8d8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@71a08c4c[portName=/dev/ttyUSB5],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@497c319a] (interrupting if necessary)
2020-02-29 18:39:12.525 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Poll task BasicPollTaskImpl@531d1e75[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@195c8d8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@71a08c4c[portName=/dev/ttyUSB5],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@497c319a] canceled
2020-02-29 18:39:12.702 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Connection pool swallowed unexpected exception:
2020-02-29 18:39:12.703 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Connection pool swallowed unexpected exception:
2020-02-29 18:40:14.738 [ERROR] [et.wimpi.modbus.net.SerialConnection] - open port failed: gnu.io.PortInUseException: Modbus Serial Master
2020-02-29 18:40:14.739 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: open port failed: Modbus Serial Master. Connection SerialConnection@1a2e8a11[portName=/dev/ttyUSB5,port=]. Endpoint ModbusSerialSlaveEndpoint@71a08c4c[portName=/dev/ttyUSB5]
2020-02-29 18:40:14.739 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: open port failed: Modbus Serial Master. Connection SerialConnection@1a2e8a11[portName=/dev/ttyUSB5,port=]. Endpoint ModbusSerialSlaveEndpoint@71a08c4c[portName=/dev/ttyUSB5]
2020-02-29 18:40:14.740 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection SerialConnection@1a2e8a11[portName=/dev/ttyUSB5,port=] for endpoint ModbusSerialSlaveEndpoint@71a08c4c[portName=/dev/ttyUSB5]: open port failed: Modbus Serial Master

20

Yes, I am using an old laptop to get a keyboard + screen + a stable SSD. It is working very well. :slight_smile:

21

This is very good log, thank you.

It seems that the following happened

  1. binding encountered I/O error when trying to communicate with the device
  2. Binding tries to close and reopen the connection (serial port), before trying again
  3. When binding tries to close the serial port, exception is raised by the underlying java serial library

Most likely the serial port is left with unclean state, explaining “port in use” errors that follow.

Have to see if I can find anything that would explain step 3) above…

EDIT: Do you have log lines before the IllegalMonitorStateException?
EDIT2: It seems that nrjavaserial version in openHAB does not have the upstream bug fix for https://github.com/NeuronRobotics/nrjavaserial/commit/f010deeb3c0367f469be338f3edf8f6528322063 , explaining the exception. Will file an issue on this to openHAB fork of nrjavaserial https://github.com/openhab/nrjavaserial

22

This shows that logging needs to be improved, we not log the underlying error properly. Will fix this. EDIT: pushed fix [modbus] Log more information on unexpected (uncatched) exceptions by ssalonen · Pull Request #7085 · openhab/openhab-addons · GitHub

23

The use case is that I would like to completely power off a device with modbus when not in use to save energy. At the same time, I also to need to disable the modbus poller to avoid spamming the log.

Surprisingly, it seems that enable and disable of the poller seems to open and close the usb port. I can see that using the lsof command. I would have thought that was controlled by Modbus Serial Slave Thing which is always enabled in my setup now.

24

There is nothing related to this before that line in the log. It is the first event in the log after I disabled the poller.

25

Yes, the use case is understood. I was poking for the circumstance that resulted in the shown error log.

Okay, this is news; you disabled poller Thing(s) at that time.
So at this point the target device is powered up or not?

Disabling (one of) your poller Thing isn’t expected to immediately stop all comms attempts, I believe the next scheduled poll will still try (at least this is what I’ve seen in my error handling procedure).

Thinking on it … a Serial Thing cannot “own” a serial port … it’s a bus system, there may be several such Serial Things sharing the same port.
It is reasonable to only “grab” the resource when needed - for read poll or asynchronous write.

That brings up back to the root issue of what is holding the port “busy”.

26

Hi @ssalonen - thanks for your effort in this.
I was wondering why the enable and disable of the poller triggers open and close of the usb port. How is then controlled if there are more pollers on the same usb port? I have several devices on the same Modbus network with each there own Modbus id and poller intended to be controlled by one single usb adapter. They are not in openHAB yet, because I was waiting for my first device to work without errors.

I would expect that you would put the open close of the usb port to the Thing level, so it is controlled by the Modbus Serial Slave. It might not entirely solve the problem, as @rossko57 writes, but I guess it would reduce it.

27

My point was that you may have multiple Serial Bridge things sharing the same port. You’ll discover that when you configure more devices. So this “top level” bridge Thing cannot “own” the port since it needs to be shared with other Things.
I realise now that I was wrong, there is simply no one Thing in this binding that can take responsibility for managing the port. So it has to be a round robin, transaction based open-use-close.

Compare with Modbus-TCP, where we structure Things in the same hierarchy. This binding’s top level TCP Thing does not “own” the system ethernet port - and we wouldn’t want it to, everyone else wants network traffic too.

Don’t lose sight that the binding releasing the port is not a problem of itself … your problem is that it can’t get it back again. Sami’s chasing that down as a mess-up when closing it.

28

Question to @rossko57 and @ssalonen :

Would it make sense to open a usb port, if a poller needs it? - and never close it again. Then you would not need any advanced logic to figure out when to close a port, and no single object would own the port.
Also, it might solve the current issue we have.
You could argue that if you choose to put a usb port in a Thing file then openHAB will claim that port.

29

This is how it works actually.

Serial connection is opened on first modbus request, and kept open/initiliased till end of time. On I/O errors the binding tries to close and open the connection, but only in those situations. This is there to try to recover properly, very relevant with tcp connections at least.

With tcp connections user can define whether connection should be closed after each request, or after some time.

Disabling thing will not cause connection close itself (al

The IllegalMonitorStateException error discussed above is a bug in serial library used by openHAB. It will be fixed in 3.x. See Is nrjavaserial still maintained? - #5 by Kai

After thinking it through, the impact of the error is actually low and probably does not explain “port in use” errors"… I will still investigate this,however. If it does cause real problems, perhaps we can convince core developers to introduce new 2.5.x openhab with the bug fix.

Any further logs might help out to diagnose the issue further. It would help to use the snapshot version of the modbus transport bundle (org.openhab.io.transport.modbus) since that contains logging fix on “swallowed exceptions” (discussed above Problem with modbus binding with dynamic on/off - #22 by ssalonen).

EDIT:

There is nothing related to this before that line in the log. It is the first event in the log after I disabled the poller.

Checking the code I would still re-check this. There should be WARN line

"Try {} out of {} failed when executing request ({}). Will try again soon. Error was I/O error, so reseting the connection. Error details: {} {} [operation ID {}]",

or ERROR

"Last try {} failed when executing request ({}). Aborting. Error was I/O error, so reseting the connection. Error details: {} {} [operation ID {}]"

Would you please copy-paste lines preceding this log line?

2020-02-29 17:58:01.031 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error invalidating connection in pool for endpoint ModbusSerialSlaveEndpoint@788895a5[portName=/dev/ttyUSB5]. Error was: java.lang.IllegalMonitorStateException null
java.lang.IllegalMonitorStateException: null
30

Hi

Here are the lines before, but I suspected that failure to be my own, because I was playing around with Modbus and I might switched + and - on RS485. That is why I wrote no errors before that. But the message you mention is present.

2020-02-29 17:57:57.791 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@6bab2106[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID ed9a92de-7275-4473-bf17-aebb9e6ddc08]
2020-02-29 17:57:59.424 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 03 00 00 00 40 44 3a
2020-02-29 17:57:59.424 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2020-02-29 17:57:59.425 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/1 error: I/O exception: IOException Error reading response (EOF). Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@6540f686 (unit id 1 & transaction 352). Serial parameters: SerialParameters@7c5dbfcb[portName=/dev/ttyUSB5,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=2,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]
2020-02-29 17:57:59.425 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute reached max tries 1, throwing last error: I/O exception: IOException Error reading response (EOF). Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@6540f686 (unit id 1 & transaction 352). Serial parameters: SerialParameters@7c5dbfcb[portName=/dev/ttyUSB5,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=2,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]
2020-02-29 17:57:59.426 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 failed when executing request (ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@6bab2106[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID ed9a92de-7275-4473-bf17-aebb9e6ddc08]
2020-02-29 17:57:59.829 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Unregistering regular poll task BasicPollTaskImpl@30a58586[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@6bab2106[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@788895a5[portName=/dev/ttyUSB5],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@497c319a] (interrupting if necessary)
2020-02-29 17:57:59.830 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Poll task BasicPollTaskImpl@30a58586[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@6bab2106[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@788895a5[portName=/dev/ttyUSB5],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@497c319a] canceled
2020-02-29 17:58:01.029 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 03 00 00 00 40 44 3a
2020-02-29 17:58:01.030 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2020-02-29 17:58:01.030 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/1 error: I/O exception: IOException Error reading response (EOF). Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@3acceea1 (unit id 1 & transaction 353). Serial parameters: SerialParameters@7c5dbfcb[portName=/dev/ttyUSB5,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=2,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]
2020-02-29 17:58:01.030 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute reached max tries 1, throwing last error: I/O exception: IOException Error reading response (EOF). Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@3acceea1 (unit id 1 & transaction 353). Serial parameters: SerialParameters@7c5dbfcb[portName=/dev/ttyUSB5,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=2,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]
2020-02-29 17:58:01.030 [ERROR] [rt.modbus.internal.ModbusManagerImpl] - Last try 3 failed when executing request (ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@6bab2106[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3]). Aborting. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: IOException Error reading response (EOF) [operation ID ed9a92de-7275-4473-bf17-aebb9e6ddc08]
2020-02-29 17:58:01.031 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error invalidating connection in pool for endpoint ModbusSerialSlaveEndpoint@788895a5[portName=/dev/ttyUSB5]. Error was: java.lang.IllegalMonitorStateException null
java.lang.IllegalMonitorStateException: null

It is really interesting that it will try to keep the port open always, and only open/close in case of i/o error.

Then I guess my setup will always hit an i/o error, because I do a power off on the device ?

Also, I have yet not blocked for that the power outlet can be manually turned off in my smart house, and I have used this in my tests as well. This means that in some situations the power was turned off, before the poller was stopped. This is of course not the long term solution, but that might be the reason for the problems ??

The long term solution is:

openhab operation turn on: power on device, wait a few seconds, and enable poller
openhab operation turn off: disable poller, wait a few seconds, power off device

manual operation turn on: power on device using wall switch input, wait some seconds and then use remote control
manual operation turn off: turn off using remote control. My openhab rule will detect this and stop poller after some seconds, wait again and then power off device

31

An i/o error will only arise if you do i/o
i.e. if you disable pollers before you kill the device (and avoid doing writes to it) then no error will arise.
EDIT - there is an implication there that you can still write to Modbus even when polled disabled. That might be useful for your “off” process.

If/when you’ve got other devices on the same serial bus, they’ll carry on the same.

That’s just an “ordinary error”, no different from a comms glitch.
It’s not the cause of your problem. “Ordinary errors” are perfectly manageable and recoverable without you doing anything special at all, recovery is built in the binding.
The kind of thing my related error management post was about is reducing impact on survivors (and logs)

1 Like