[SOLVED] Serial port only opening once after startup

  • Platform information:
    • Hardware: MARVELL Armada 370 / 512M
    • OS: Synology DSM 6.2.2
    • Java Runtime Environment: 8.0.202
    • openHAB version: 2.5 M4

I am using the RFLink binding that is connected to /dev/ttyUSB0.
But I can not get the serial port to work if it is enabled will I start openhab.
If I disable the RFLink bridge in the PaperUI and restart openhab then it will work one time when I enable it but if I disable it and re-enable it, it will not work again.
I have also tried to use the serial binding and it looks like this has the same issues, I can get it to work once but not if it is installed while starting. ( I can not test in the exact same way because the is no bridge to disable )

So am a guessing it has something to do with nrjavaserial and not RFLink.

Because it is working once I guess the access rights are configured correctly.
But just to for the record.

/$ ls -l /dev/ttyUSB*
crwxrwxrwx 1 root uucp 188, 0 Nov 17 08:40 /dev/ttyUSB0
/$ grep uucp /etc/group
uucp:x:65538:openhab

I added “-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0” to runtime/bin/setenv
I use “sudo insmod ch341.ko” to load the driver.

The log I get looks like this when it is enabled for the first time and then disabled / enabled.

2019-11-17 09:37:50.108 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Initializing RFLink bridge handler
2019-11-17 09:37:50.135 [DEBUG] [rflink.internal.RfLinkHandlerFactory] - RfLinkHandlerFactory createHandler(rflink:rts:usb0:somfy_blinds)
2019-11-17 09:37:50.148 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Checking RFLink transceiver connection, thing status = OFFLINE
2019-11-17 09:37:50.151 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Connecting to RFLink transceiver on /dev/ttyUSB0 port
2019-11-17 09:37:50.179 [DEBUG] [link.connector.RfLinkSerialConnector] - RfLinkRxTxConnector()
2019-11-17 09:37:50.215 [DEBUG] [link.connector.RfLinkSerialConnector] - Disconnecting
2019-11-17 09:37:50.217 [DEBUG] [link.connector.RfLinkSerialConnector] - Closed
2019-11-17 09:37:50.224 [DEBUG] [link.connector.RfLinkSerialConnector] - connect(/dev/ttyUSB0)
2019-11-17 09:37:50.258 [DEBUG] [link.connector.RfLinkSerialConnector] - Found port : /dev/ttyUSB0
2019-11-17 09:37:50.315 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - RFLink receiver started
2019-11-17 09:37:50.313 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - Initializing thing rflink:rts:usb0:somfy_blinds, deviceId=RTS-02F632-0
2019-11-17 09:37:50.335 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - initializeBridge ONLINE for thing rflink:rts:usb0:somfy_blinds
2019-11-17 09:37:50.339 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - bridgeStatusChanged ONLINE for thing rflink:rts:usb0:somfy_blinds
2019-11-17 09:37:50.359 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - Received channel: rflink:rts:usb0:somfy_blinds:shutter, command: REFRESH
2019-11-17 09:37:50.363 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - initializeBridge ONLINE for thing rflink:rts:usb0:somfy_blinds
2019-11-17 09:37:51.205 [DEBUG] [link.connector.RfLinkSerialConnector] - <<< 20;00;Nodo RadioFrequencyLink - RFLink Gateway V1.1 - R48;
2019-11-17 09:38:14.318 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - Thing rflink:rts:usb0:somfy_blinds disposed.
2019-11-17 09:38:14.442 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Handler disposed.
2019-11-17 09:38:14.444 [DEBUG] [link.connector.RfLinkSerialConnector] - Disconnecting
2019-11-17 09:38:17.447 [DEBUG] [link.connector.RfLinkSerialConnector] - Serial port event listener stopped
2019-11-17 09:38:17.450 [DEBUG] [link.connector.RfLinkSerialConnector] - Close serial out stream
2019-11-17 09:38:17.458 [DEBUG] [link.connector.RfLinkSerialConnector] - Close serial in stream
2019-11-17 09:38:19.453 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'rflink:bridge:usb0' takes more than 5000ms.
2019-11-17 09:38:19.473 [DEBUG] [org.openhab.binding.rflink          ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=397, service.bundleid=208, service.scope=singleton} - org.openhab.binding.rflink
2019-11-17 09:38:45.833 [DEBUG] [rflink.internal.RfLinkHandlerFactory] - RfLinkHandlerFactory createHandler(rflink:bridge:usb0)
2019-11-17 09:38:45.851 [DEBUG] [org.openhab.binding.rflink          ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=409, service.bundleid=208, service.scope=singleton} - org.openhab.binding.rflink
2019-11-17 09:38:45.907 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Initializing RFLink bridge handler
2019-11-17 09:38:45.919 [DEBUG] [rflink.internal.RfLinkHandlerFactory] - RfLinkHandlerFactory createHandler(rflink:rts:usb0:somfy_blinds)
2019-11-17 09:38:45.929 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Checking RFLink transceiver connection, thing status = OFFLINE
2019-11-17 09:38:45.934 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Connecting to RFLink transceiver on /dev/ttyUSB0 port
2019-11-17 09:38:45.937 [DEBUG] [link.connector.RfLinkSerialConnector] - RfLinkRxTxConnector()
2019-11-17 09:38:45.956 [DEBUG] [link.connector.RfLinkSerialConnector] - Disconnecting
2019-11-17 09:38:45.958 [DEBUG] [link.connector.RfLinkSerialConnector] - Closed
2019-11-17 09:38:45.973 [DEBUG] [link.connector.RfLinkSerialConnector] - connect(/dev/ttyUSB0)
2019-11-17 09:38:45.992 [DEBUG] [link.connector.RfLinkSerialConnector] - Found port : /dev/ttyUSB0
2019-11-17 09:38:46.001 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - Initializing thing rflink:rts:usb0:somfy_blinds, deviceId=RTS-02F632-0
2019-11-17 09:38:46.003 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - initializeBridge OFFLINE for thing rflink:rts:usb0:somfy_blinds
2019-11-17 09:38:46.015 [DEBUG] [ng.rflink.handler.RfLinkThingHandler] - Received channel: rflink:rts:usb0:somfy_blinds:shutter, command: REFRESH
2019-11-17 09:38:47.995 [ERROR] [g.rflink.handler.RfLinkBridgeHandler] - Connection to RFLink transceiver failed: org.openhab.binding.rflink.connector.RfLinkSerialConnector
2019-11-17 09:38:50.339 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Checking RFLink transceiver connection, thing status = OFFLINE
2019-11-17 09:38:50.342 [DEBUG] [g.rflink.handler.RfLinkBridgeHandler] - Connecting to RFLink transceiver on /dev/ttyUSB0 port
2019-11-17 09:38:50.343 [DEBUG] [link.connector.RfLinkSerialConnector] - Disconnecting
2019-11-17 09:38:50.346 [DEBUG] [link.connector.RfLinkSerialConnector] - Serial port event listener stopped
2019-11-17 09:38:50.348 [DEBUG] [link.connector.RfLinkSerialConnector] - Close serial out stream
2019-11-17 09:38:50.349 [DEBUG] [link.connector.RfLinkSerialConnector] - Close serial in stream

I looked in the source code for RFLink and I can see that the ERROR message (Connection to RFLink transceiver failed) is from a java exception that RFLink is catching but I do not know where this might originate from.

Any advice on how I can resolve this issue is appreciated.

I am not sure that is where the line belongs. When I tested a different binding I added it to /etc/defaults/openhab2 file. In some cases I added the parameters to the existing Java Opts.

I can see that the parameter is added when I do a

ps aux | grep ttyUSB0
openhab 27103 8.9 47.7 361672 243308 ? Sl 09:33 4:32 /var/packages/Java8/target/j2sdk-image/jre/bin/java -Dop… -Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0 -Dj… org.apache.karaf.main.Main

I stripped down the line.
I have also tried without the line and then it does not work at all.

Regarding etc/defaults/openhab2 I am unsure exactly where this should be. I do not have folder called /etc/defaults in the root. but is this some path that openhab is hardcoded to search for?

Sorry I typed that from memory. It should have been /etc/default/openhab2

Here is a quote from the Linux installation guide.

An openHAB setup will often rely on hardware like a modem, transceiver or adapter to interface with home automation hardware. Examples are a Bluetooth, Z-Wave, Enocean or RXFcom USB Stick or a Raspberry Pi add-on board connected to the serial port on its GPIOs. In order to allow openHAB to communicate with additional peripherals, it has to be added to corresponding Linux groups. The following example shows how to add Linux user openhab to the often needed groups dialout and tty. Additional groups may be needed, depending on your hardware and software setup.

sudo adduser openhab dialout
sudo adduser openhab tty
sudo adduser openhab bluetooth
If you are looking to enable sound privileges for openHAB, it will also be necessary to add openHAB to the "audio" group.

sudo adduser openhab audio
Additionally it's needed to allow the java environment to access the serial port of the connected peripheral. Therefore the following setting has to be added/adapted on your system in file /etc/default/openhab2:

EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"
The shown device handlers are just the most common examples. Please contact the community forum for more detailed information regarding individual hardware.

From

I did not use the dialout and tty groups but I have added a uucp group and added the openhab user to that group. ( on my Synology the dialout and tty groups do not exist )
I also set the permissions with “sudo chmod 777 /dev/ttyUSB0” so that everybody should have access in an attempt to ensure it was not a access issue.
Do you think it can be a permission issue when it is working once and then just because I disable and enable in PaperUI it stops working. Should strange.

Also the /etc/default/ folder does not exist I guess this is for debian installs. I think the service is started a bit differently on Synology.
I can of cause try and create the “default” folder but there is no /etc/init.d/ folder either.

Sounds more like something not releasing the port. Only one service use hold a serial port at a time.
Alternatively, “something else” grabs the port when you release it. I can’t imagine what. Not sure what happens if you have two Things configured (or cached) for the same port - maybe there is a queue action.

I just tried to update to the new milestone version 2.5 M5 and the issue is the same.
If I start with the rflink disabled I get this before I start it.

openhab> smarthome:serial identifiers
[name: /dev/ttyUSB0, current owner: null]
[name: /dev/ttyACM0, current owner: org.openhab.binding.zwave]

Then I tried to enable it and I get this.

openhab> smarthome:serial identifiers
[name: /dev/ttyUSB0, current owner: org.openhab.binding.rflink.connector.RfLinkSerialConnector]
[name: /dev/ttyACM0, current owner: org.openhab.binding.zwave]

When I disable it, I still get the same, so it clearly looks like RFLink is not releasing the serial port correctly and If I start with RFlink enabled then I also get the same result.
So maybe RFlink connects and disconnect during startup and therefore can not access the port the second time it tries.

What “it” ?

Which result - ttyUSB0 is owned by null or RFLink ? Just trying to be clear.

it = RFLink

It is owned by RFLink despite the PaperUI showing RFLink USB Transceiver as offline

Okay, let’s try a bit more. “RFLink” is a Bridge Thing you have configured for the experimental RFLink binding?
I assume there is one and only one such Thing.

If you have been editing this RLink Thing, experience from other bindings suggests that sometimes you need to clear out old erroneous config by going through the clean cache routine.

While openHAB is stopped I would also make sure to clear out old serial config - being a 1.x binding, you should have removed serial.cfg but you should also search for and remove serial.config file (which is effectively a cached version)

In truth though, I suspect -

Changes were made to serial handling during 2.5 development.
I don’t think the incomplete RFLink binding has had any updates in the last nine months? so it probably is not compatible with OH2.5M4

I think you may need to go back to OH2.4

Yes RFLink is a Bridge that I disable/enable.
When I did the upgrade to 2.5 M5 I only kept the conf, addons and a few other folders so I think any cashed files are removed.
After your last comment I decided to go back and try with the serial binding again and after the upgrade to M5 it looks like it is working.
For the record this is the line I used to replace the RFLink binding.

Rollershutter kitchen_blinds { autoupdate=“false”, serial="/dev/ttyUSB0@57600,UP(10;RTS;02F632;0;UP;\n),DOWN(10;RTS;02F632;0;DOWN;\n),STOP(10;RTS;02F632;0;STOP;\n)" }

Thanks a lot for your help.

Okeydoke, are we going to put that down that maybe RLink binding current development version is not (yet) suitable for 2.5 ? I know there were changes around serial libraries affecting several bindings, but don’t knows the details.

This may need feeding back to binding author.

I made a post on the RFLink binding thread