Problem with modbus binding with dynamic on/off

Hi
My use case is that I trying to control a Panasonic AirCondition using Modbus binding. I am using USB on an Ubunto box to connect and I have configured a 99-openhab.rules with udev. So I have no problem with shifting USB names or permissions.

If I have my AirCondition always powered on everything is working fine in the binding in all situations.

However, the AirCondition seem to have a quite high standby power consumption including the 2 indoor units. Therefore, to save power I have implemented this when it is turned on from openHAB:

  1. Turn on power relay to AirCondition
  2. Wait 10 seconds
  3. Rename AirCond.thingsIncative file to AirCond.things
  4. Wait 5 seconds
  5. Set AirCondition state to what is requested from openHAB.

The rename is to get that thing active in Modbus and openHAB. When the AirCond is shut off, I do reverse of above.

The problem is that it is not stable, so sometimes I get that the USB port is already in use, and the log is spammed. A restart of openhab solves it, but that is not a good solution. It seems that the usb port is not always released and closed.

I have also tried dynamicly to start and stop the modbus binding using karaf console, but that is even less stable. The problem is the same, that sometimes it says that the usb port is already in use.

The best option for me would be if the binding had ā€œActive true/falseā€ as a property on the bridge or poller. But this does not exist.

Any suggestions would be very welcome. Also if it is possible to force a release of the usb port by a Linux OS command or similar.

Alerting the senior modbus guys : @rossko57, @ssalonen
Thanks.

See


which describes how to automatically disable TCP/Serial bridge Thing temporarily in a fault situation.
You should be able to extract just the sendHttpPutRequest() bit you need to do that under control of your timed rules instead.

You might prefer to disable poller Things only, since youā€™ll only have one/few, which should allow the serial Thing to keep hold of the serial port.

Please see Rosskos advice on the disable /enable of polling.

Regarding serial port errors : I have seen similar behavior reported before but I have not been able to get proper steps to reproduce the issue, until now.

Would you be able enable verbose logging (see modbus binding docs) and capture the log? Since it does not happen always, would be super useful to have logs of the positive sequence of events as well.

This would looking into the issue closer and fix the underlying bug.

Thank you very much. Seems a little advanced to my level, but I will certainly look at it.
I am travelling for the next 10 days, so I cannot try this until later.

As I say, you just need the http requests to REST API shown in the rule, that disable and re-enable Things,using their UID.
Most of the code there is about detecting errors and identifying culprits, you donā€™t need that for your timed sequence with known target Things.

You can choose to disable serial Thing, shutting down whole Modbus ā€œdevice modelā€.
Iā€™d try disabling just your poller Thing(s) though, as that should leave serial Thing in possession of the USB port, but avoid trying to periodically read poll a ā€œdeadā€ device.
If you try to write to it, thatā€™s your problem :wink:

Once thatā€™s working, you might need to consider your Item states. I donā€™t think disabling modbus Things is going to automatically flag UNDEF in associated Items, they would just stay on last valid reading.
You might choose to handle that in rules, or use expire binding as in the error management thread.

1 Like

Thanks - very informative. Does this still require the json in the karaf for the http to be working?

I donā€™t know what that means.

Let me spend some more time on this, so I know it better. Then I can make more qualified questions :wink:

For now it is important info from you that keeping the Thing holds the usb, while stopping the poller can avoid spamming the log with error message, if a device is turned off.

Thanks @rossko57 for pointing me in the direction of Rest API for openHAB, which I did not know.

My poller has this Thing name: modbus:serial:slave01:holdingsREG
and I ended up with this for disable:

sendHttpPutRequest(ā€œhttp://192.168.1.2:8079/rest/things/modbus%3Apoller%3Aslave01%3AholdingsREG/enableā€, ā€œapplication/jsonā€, ā€˜disabledā€™)

and for enabling:

sendHttpPutRequest(ā€œhttp://192.168.1.2:8079/rest/things/modbus%3Apoller%3Aslave01%3AholdingsREG/enableā€, ā€œapplication/jsonā€, ā€˜trueā€™)

which seems to work. However, I have to test it more, because the error with the usb port only comes periodically.
Please note I am using port 8079 instead of default port 8080, which is occupied by another application.

Iā€™m only assuming that is true. It might timeout and release the port with no actual traffic, I donā€™t know.

Unfortunately, the problem still exists. If I restart openHAB and try on and off several times everything is fine. Then I went to bed with the poller disabled (=no traffic on the port) and I tried again next morning and then I got the error message shown below:

2020-02-17 17:37:15.667 [ERROR] [et.wimpi.modbus.net.SerialConnection] - open port failed: gnu.io.PortInUseException: Modbus Serial Master
2020-02-17 17:37:15.668 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: open port failed: Modbus Serial Master. Connection SerialConnection@2a0e4fb7[portName=/dev/ttyUSB5,port=]. Endpoint ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5]
2020-02-17 17:37:15.668 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: open port failed: Modbus Serial Master. Connection SerialConnection@2a0e4fb7[portName=/dev/ttyUSB5,port=]. Endpoint ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5]
2020-02-17 17:37:15.669 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection SerialConnection@2a0e4fb7[portName=/dev/ttyUSB5,port=] for endpoint ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5]: open port failed: Modbus Serial Master
2020-02-17 17:37:15.670 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5] ā€“ aborting request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@6b33458c[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=64,maxTries=3] [operation ID bd096801-34b0-42de-9c84-3df767cac0fa]
2020-02-17 17:37:15.671 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave01:holdingsREG:Thac1unitonoff ā€˜Modbus Dataā€™ had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5])
2020-02-17 17:37:15.672 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave01:holdingsREG:Thac1unitfanspeed ā€˜Modbus Dataā€™ had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5])
2020-02-17 17:37:15.673 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave01:holdingsREG:Thac1unitmode ā€˜Modbus Dataā€™ had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusSerialSlaveEndpoint@680894d1[portName=/dev/ttyUSB5])

With the orginal rename in things file, I got the error message that port was already in use. Now I am only disabling the poller, and it says could not open usb port. So the question is: why does it have to open the port, because the usb port is owned by the Thing Bridge, which has been online all the time?

To me this indicates that @rossko57 might be right in his assumption that the port can be released with no traffic.

When I moved from openHAB 2.4 to 2.5 I had to install EXTRA_JAVA_OPTS to make the very same code work. In openHAB 2.4 I did not have to install this. Can it be somewhere in Java framework or Linux which changes the port status?

@Kim_Andersen : I know you have also been using Modbus USB for your Nilan products. Do you have any observations which is relevant for this scenario?

For now I think I will the order a tcp modbus adapter, because I am really burning many hours on this, and I hope that another type of connection might solve the problem.

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:

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?

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

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.

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

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

@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:

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

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