[SOLVED] USB device no longer exists after upgrading OpenHab 2.3.0 -> 2.4.0-M5

I’ve upgraded from 2.3.0 to 2.4.0-M5 in order to resolve some problems with the ZigBee binding.

Unfortunately since upgrading (with yum from the Testing repo), OH can no longer access the serial ports (USB devices):

2018-11-01 15:39:55.967 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2018-11-01 15:39:56.970 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2018-11-01 15:39:56.971 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2018-11-01 15:39:56.971 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported cluster 1280
2018-11-01 15:39:56.972 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher starting
2018-11-01 15:39:56.973 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher adding cluster IAS_ZONE
2018-11-01 15:39:56.974 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported cluster 25
2018-11-01 15:39:56.974 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - ClusterMatcher adding cluster OTA_UPGRADE
2018-11-01 15:39:56.975 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP dongle initialize with protocol ASH2.
2018-11-01 15:39:56.976 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB1] at 57600 baud, flow control FLOWCONTROL_OUT_XONOFF.
2018-11-01 15:39:56.985 [ERROR] [ding.zigbee.handler.ZigBeeSerialPort] - Serial Error: Port /dev/ttyUSB1 does not exist.
2018-11-01 15:39:56.985 [ERROR] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unable to open Ember serial port
2018-11-01 15:39:56.989 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Start.

Nothing else has changed, it seems like the upgrade process broke something?

[root@nexus ~]# dmesg | grep -i usb
[    0.114751] ACPI: bus type USB registered
[    0.114776] usbcore: registered new interface driver usbfs
[    0.114791] usbcore: registered new interface driver hub
[    0.114811] usbcore: registered new device driver usb
[    0.713147] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.713172] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.713193] uhci_hcd: USB Universal Host Controller Interface driver
[    0.713445] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 1
[    0.714649] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.714653] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.714656] usb usb1: Product: xHCI Host Controller
[    0.714660] usb usb1: Manufacturer: Linux 3.10.0-862.14.4.el7.x86_64 xhci-hcd
[    0.714663] usb usb1: SerialNumber: 0000:00:14.0
[    0.714817] hub 1-0:1.0: USB hub found
[    0.715524] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
[    0.715570] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
[    0.715574] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.715577] usb usb2: Product: xHCI Host Controller
[    0.715580] usb usb2: Manufacturer: Linux 3.10.0-862.14.4.el7.x86_64 xhci-hcd
[    0.715583] usb usb2: SerialNumber: 0000:00:14.0
[    0.715719] hub 2-0:1.0: USB hub found
[    0.715981] usbcore: registered new interface driver usbserial
[    0.715991] usbcore: registered new interface driver usbserial_generic
[    0.716000] usbserial: USB Serial support registered for generic
[    1.759765] usbcore: registered new interface driver usbhid
[    1.759768] usbhid: USB HID core driver
[    2.010083] usb 1-4: new full-speed USB device number 2 using xhci_hcd
[    2.175268] usb 1-4: string descriptor 0 read error: -22
[    2.175280] usb 1-4: New USB device found, idVendor=04ca, idProduct=3007
[    2.175284] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.328206] usb 1-6: new full-speed USB device number 3 using xhci_hcd
[    2.493755] usb 1-6: New USB device found, idVendor=10c4, idProduct=8a2a
[    2.493761] usb 1-6: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[    2.493765] usb 1-6: Product: HubZ Smart Home Controller
[    2.493769] usb 1-6: Manufacturer: Silicon Labs
[    2.493772] usb 1-6: SerialNumber: 61200DD8
[    4.374196] usbcore: registered new interface driver cp210x
[    4.374230] usbserial: USB Serial support registered for cp210x
[    4.377679] usb 1-6: cp210x converter now attached to ttyUSB0
[    4.380792] usb 1-6: cp210x converter now attached to ttyUSB1
[    4.661909] usbcore: registered new interface driver btusb
[    4.823824] usb 1-4: USB disconnect, device number 2
[    4.824335] usbcore: registered new interface driver ath3k
[    5.107036] usb 1-4: new full-speed USB device number 4 using xhci_hcd
[    5.272340] usb 1-4: string descriptor 0 read error: -22
[    5.272352] usb 1-4: New USB device found, idVendor=04ca, idProduct=3007
[    5.272356] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3

[root@nexus ~]# lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 10c4:8a2a Cygnal Integrated Products, Inc. 
Bus 001 Device 004: ID 04ca:3007 Lite-On Technology Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

[root@nexus ~]# grep -i usb /etc/default/openhab2 
##   EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"
EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyUSB1:/dev/ttyUSB2:/dev/ttyS0:/dev/ttyS2"

openhab   2049  7.7 23.4 3244568 449616 ?      Ssl  13:53   0:57 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djava.library.path=/var/lib/openhab2/tmp/lib -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening.addresses=0.0.0.0 -Dorg.osgi.service.http.port=8080 -Dorg.osgi.service.http.port.secure=8443 -Djava.awt.headless=true -XX:+UseG1GC -Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyUSB1:/dev/ttyUSB2:/dev/ttyS0:/dev/ttyS2 -Djava.endorsed.dirs=/usr/lib/jvm/zulu-8/jre/lib/endorsed:/usr/lib/jvm/zulu-8/lib/endorsed:/usr/share/openhab2/runtime/lib/endorsed -Djava.ext.dirs=/usr/lib/jvm/zulu-8/jre/lib/ext:/usr/lib/jvm/zulu-8/lib/ext:/usr/share/openhab2/runtime/lib/ext -Dkaraf.instances=/var/lib/openhab2/tmp/instances -Dkaraf.home=/usr/share/openhab2/runtime -Dkaraf.base=/var/lib/openhab2 -Dkaraf.data=/var/lib/openhab2 -Dkaraf.etc=/var/lib/openhab2/etc -Dkaraf.logs=/var/log/openhab2 -Dkaraf.restart.jvm.supported=true -Djava.io.tmpdir=/var/lib/openhab2/tmp -Djava.util.logging.config.file=/var/lib/openhab2/etc/java.util.logging.properties -Dkaraf.startLocalConsole=false -Dkaraf.startRemoteShell=true -classpath /usr/share/openhab2/runtime/lib/boot/activation-1.1.1.jar:/usr/share/openhab2/runtime/lib/boot/jaxb-api-2.3.0.jar:/usr/share/openhab2/runtime/lib/boot/jaxb-core-2.2.11.jar:/usr/share/openhab2/runtime/lib/boot/jaxb-impl-2.2.11.jar:/usr/share/openhab2/runtime/lib/boot/jna-4.5.2.jar:/usr/share/openhab2/runtime/lib/boot/jna-platform-4.5.2.jar:/usr/share/openhab2/runtime/lib/boot/org.apache.karaf.diagnostic.boot-4.2.1.jar:/usr/share/openhab2/runtime/lib/boot/org.apache.karaf.jaas.boot-4.2.1.jar:/usr/share/openhab2/runtime/lib/boot/org.apache.karaf.main-4.2.1.jar:/usr/share/openhab2/runtime/lib/boot/org.osgi.core-6.0.0.jar org.apache.karaf.main.Main

[root@nexus ~]# groups openhab
openhab : openhab tty dialout audio

[root@nexus ~]# ls -l /dev/ttyUSB*
crw-rw---- 1 root dialout 188, 0 Nov  1 13:45 /dev/ttyUSB0
crw-rw---- 1 root dialout 188, 1 Nov  1 13:45 /dev/ttyUSB1

-bash-4.2$ whoami
openhab
-bash-4.2$ cat /dev/ttyUSB1 
^C

SELinux is disabled. I have rebooted, restarted etc, no luck.

Any ideas?

Check to see if there is a /var/lock/LCK…ttyXXXX file where XXXX corresponds with the serial device that is not working.

I’ve been having problems with OH not deleting the lock file for the devices but I’m running in Docker and assumed it was a Docker issue.

ah was unaware of those… unfortunately nothing (maybe those are container specific?)

[root@nexus lock]# pwd
/var/lock

[root@nexus lock]# find
.
./kdump
./subsys
./subsys/network
./lockdev
./lvm
[root@nexus lock]#

so it looks like nrjavaserial jar was upgraded from 3.12.0.OH to 3.14.0 between 2.3.0 and 2.4.0-M5

Ok - got it working again, you were on the right track @rlkoshak (cc @chris).

Wanted to try out that latest NRJavaSerial jar so wrote a quick test program:

import gnu.io.*;
import java.io.*;

public class TestSerialPort {
    public static void main(String[] args) {
	for(String s:NRSerialPort.getAvailableSerialPorts()){
			System.out.println("Available port: " + s);
		}
	String port = "/dev/ttyUSB1";
	int baudRate = 57600;
	NRSerialPort serial = new NRSerialPort(port, baudRate);
	serial.connect();

	DataInputStream ins = new DataInputStream(serial.getInputStream());
	DataOutputStream outs = new DataOutputStream(serial.getOutputStream());

        try {
	int b = ins.read();
	outs.write(b);
	} catch (IOException e) {
		System.err.println(e);
	}

	serial.disconnect();
        System.out.println("all done!");
    }
}

ran fine as root. Then tried as the openhab user and bam:

-bash-4.2$ java -cp /usr/share/openhab2/runtime/system/com/neuronrobotics/nrjavaserial/3.14.0/nrjavaserial-3.14.0.jar:. TestSerialPort
check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission to create lock file.
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: Permission denied. FAILED TO OPEN: No such file or directory
?o?? testRead() Lock file failed

check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission to create lock file.
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: Permission denied. FAILED TO OPEN: No such file or directory
?o?? testRead() Lock file failed
check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission to create lock file.
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS3: Permission denied. FAILED TO OPEN: No such file or directory
?o?? testRead() Lock file failed

not the most secure solution but for now I did a chmod a+w /var/lock … and everything started working again. Guess the serial ports don’t allow concurrent access?

1 Like

Interesting, I found this really helpful article on the problem.

Perhaps there is something for us to do to the RPM scripts here?

1 Like

if only I checked the systemd journal!

Well, for those still having the issue after checking /var/lock permissions (as myself), please have a look at this post related to the Zigbee binding

nrjavaserial seems to need some native libraries (i.e. liblockdev). In my raspbian distro, I could not find a binary package and I had to manually compile and install it (instructions in the post above).

Pedro

Just on my “security-conscious” side, I would suggest to use chmod a+w,+t /var/lock instead.

This will at least add the sticky bit, so that once created, the files inside cannot be replaced by another user.

Pedro

1 Like