Locking error using zwave in fedora 22

donniet · October 6, 2015, 9:24pm

Hello,
I have a simple openhab 1.7.1 starter setup using a z-wave aeon usb stick and a couple of door sensors. I’ve noticed that the instructions related to adding the dialout group to the openhab user do not work in at least fedora 22. In fedora 22 /var/lock has been moved and the permissions changed. Details are in the changelog here

I think the problem is inside of nrjavaserial-3.9.3.jar which is included in openhab-1.7.1. There is a hard define of LOCKDEV to /var/lock (see line 166 of _https://github.com/NeuronRobotics/nrjavaserial/blob/02d9a5bdfc94a9812c501d8666464ce4c307440b/nrjavaserial/src/main/c/include/SerialImp.h). In the newest version, nrjavaserial-3.10.0 this issue appears to be fixed (see that liblockdev is used on line 400 of _https://github.com/NeuronRobotics/nrjavaserial/blob/master/nrjavaserial/src/main/c/include/SerialImp.h)

I’ve temporarily fixed it by changing the owner of the /run/lock folder to uucp 0775 and it works fine (until the next boot), so I know that the problem is not the groups that openhab is running as (i followed the instructions on the wiki). Below are my logs to show the error, and any pointers or help would be appreciated!

Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.247 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyUSB0
Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.247 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, healtime = 2
Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.249 [INFO ] [.service.AbstractActiveService] - ZWave Refresh Service has been started
Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.261 [INFO ] [b.z.i.protocol.ZWaveController] - Starting Z-Wave controller
Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.265 [INFO ] [b.z.i.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is fa
Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.265 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyUSB0
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: Permission denied. FAILED TO OPEN: No such file or
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS3: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS2: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS1: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS0: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: Permission denied. FAILED TO OPEN: No such file or
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS3: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS2: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS1: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS0: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: Permission denied. FAILED TO OPEN: No such file or
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS3: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS2: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS1: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: check_group_uucp(): error testing lock file creation Error details:Permission deniedcheck_lock_status: No permission
Oct 06 15:12:38 backend start-systemd.sh[17839]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS0: Permission denied. FAILED TO OPEN: No such file or d
Oct 06 15:12:38 backend start-systemd.sh[17839]: [34B blob data]
Oct 06 15:12:38 backend start-systemd.sh[17839]: 2015-10-06 15:12:38.275 [ERROR] [b.z.i.protocol.ZWaveController] - Serial Error: Port /dev/ttyUSB0 does not exist

and here are the relevant config areas:

################################ Z-Wave  Binding ######################################
#
# The Z-Wave controller port. Valid values are e.g. COM1 for Windows and /dev/ttyS0 or
# /dev/ttyUSB0 for Linux
zwave:port=/dev/ttyUSB0

# Z-Wave nightly heal time. This is the hour (eg 2AM) at which the automatic nightly
# network heal will be performed.
zwave:healtime=2

JjS · January 16, 2016, 10:22pm

To fix it permanently check the default permission for directories recreated at boot. In centos I had to edit /usr/lib/tmpfiles.d/legacy.conf and change permission in the line:

d /run/lock 0775 root lock -

jcollie · February 23, 2016, 3:54pm

That does not seem like a permanent “fix” to me, it seems more like a permanent workaround for the fact that the directory that openHAB uses for lock files can’t be modified, at least not without recompiling.

chris · February 23, 2016, 4:45pm

Ultimately, it’s not an issue with openHAB (unfortunately - if it was, we could fix it). A ‘real’ permanent solution needs to be made in the serial library but that seems quite slow from what I could see looking at the GH issue last week

JjS · February 23, 2016, 4:56pm

The fix presented by Donnie lasted till the next reboot, my is permanent in the sense it survives OS restart. It gets overwritten upon some updates…