Another Zwave /dev/ttyACM0 not found

[ptmuldoon (Paul Muldoon)]

I have been struggling with this issue for over a month now and short of a reinstall of Ubuntu from scratch at I’m at loss to to why this is happening.

For the past month or so, Whenever I do a reboot of the machine, I’m am told the Controller is offline.

And the only solution I have come up with is to 1) remove the device from the machine, 2) plug it back in, 3) change the port to ttyACM1. Only then can i get the controller to come online and things to start working again.

I’m happy to post some log info, but wanted to check first if anyone has any ideas what could be causing this. I do not suspect OH2 fully and permissions seem fine as the controller starts fine on ACM1.

Its just when you get the random loss of power or any other random reboot issue, I have to manually unplug and replug to get the device to work.

Edit: Forgot to mention this is with an Aeon Gen5 Stick as well running on Ubuntu 16 Server.

[RHINESEL (Matthew Valeri)]

Did you add the libraries mentioned in this thread:

https://community.openhab.org/t/oh2b5-and-dev-ttyacm0-z-wave/18783/25

[nolan_garrett]

I am not certain this would make a difference if the issue is port naming. @ptmuldoon I am running a similar configuration to yours, but do not have this issue. My device always comes up on ttyACM0 on any reboot or power cycle, however, I can replicate the issue you mention if I remove the Z-Stick and re-plug it without rebooting. Based on what you are reporting here, my guess is that this is a Linux configuration of some kind and not an issue with OpenHAB at all.

I am running Ubuntu 16.04.1 LTS.

[shorty707]

for months I am running OH2 now.

Today I upgraded to @chris zwave snapshot from yesterday.

Since then I get that error and nothing helps to get the stick again
when I do ls /dev/tty* I can see there is still the ACM0

8:44:36.107 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
java.lang.UnsatisfiedLinkError: gnu.io.RXTXCommDriver.nativeGetVersion()Ljava/lang/String; thrown while loading gnu.io.RXTXCommDriver
java.lang.NoClassDefFoundError: Could not initialize class gnu.io.RXTXCommDriver thrown while loading gnu.io.RXTXCommDriver
08:44:38.198 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:15348538564' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to OFFLINE (COMMUNICATION_ERROR): Serial Error: Port /dev/ttyACM0 does not exist

[jaydee73 (Stefan)]

Have you only updated the zwave binding or everything via apt-get?

There is some discussion going around (see the thread posted by @RHINESEL above)… Some had success with installing the mentioned libraries.

[shorty707]

@jaydee73

Have you only updated the zwave binding or everything via apt-get?

There is some discussion going around (see the thread posted by @RHINESEL above)… Some had success with installing the mentioned libraries.

ONLY zwave binding… that was the odd thing.

I did the following now and that worked and the stick is found again during OH startup

Nrjavaserial upgrade causes "Serial Error: Port /dev/ttyACM0 does not exist"

I was having a similar issue with an existing install. Did two things in parallel and one of them fixed it: Installed this library: RFXCom issue on RP3 And did an apt-get update/upgrade and am now back online. Hope one or both help your install (I’d start with an upgrade).

[chris (Chris Jackson)]

@shorty707

ONLY zwave binding… that was the odd thing.

That’s unlikely I think…

Karaf handles dependencies for you so it will also upgrade these as well. So you will have also upgraded to the new serial library that is causing all the problems…

[shorty707]

well what I did this morning was:

• uninstall ZWAVE 2.0 via PaperUI

• install ZWAVE 2.0 via PaperUI

• restart OH

I did not check log if automatically any dependencies were triggered

[chris (Chris Jackson)]

Yep - so as I said, I think it will have installed the new serial library as well and that will explain your problem it seems.

To add - dependencies are always loaded - otherwise it won’t work

[Kai (Kai Kreuzer)]

Please wait for the next build and then try again - the serial lib change has just been reverted.

[ptmuldoon (Paul Muldoon)]

Anyword on when to expect the next build? I apt-get updated and upgraded yesterday but still had same issues with ttyACM0.

[Kai (Kai Kreuzer)]

The build is done almost daily, see https://openhab.ci.cloudbees.com/job/openHAB-Distribution/

The revert is in the distro since 4 days already.
If you still have problems, it is something different than before.

[ptmuldoon (Paul Muldoon)]

I must having a different issue then. I just went and did the following in trying to resolve.

1. Uninstalled the Zwave binding.
2. Stopped OH2
3. Did a sudo apt-get update and upgrade (no upgrades were actually needed)
4. Restarted OH2 and Reinstalled the Zwave binding
5. Set the Controller in Habmin to /dev/ttyACM0
6. Rebooted the machine.

I do know there is LCK file on the device being created, but it also seem to be being created by OH2 as well. the LCK…ttyACM0 shows a process id of 1676 (id will change with a reboot, etc)

But when I check that process id in Ubuntu, I get this"

ptmuldoon@UbuntuHA:/var/lock$ ls
apache2  LCK..ttyACM0  lvm  subsys
ptmuldoon@UbuntuHA:/var/lock$ ps 1676
  PID TTY      STAT   TIME COMMAND
 1676 ?        Sl     1:54 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dop
ptmuldoon@UbuntuHA:/var/lock$

And I stop OH2 with sudo systemctl stop openhab2.service the LCK file disappears, so pretty sure OH2 is seeing the controller.

And my OH2 log on a Reboot shows this:

2016-12-31 16:00:39.984 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2016-12-31 16:00:40.098 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.0.0.b5
2016-12-31 16:00:40.187 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=200, service.id=329, service.bundleid=218, service.scope=bundle} - org.openhab.binding.zwave
2016-12-31 16:00:40.189 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=201, service.id=330, service.bundleid=218, service.scope=bundle} - org.openhab.binding.zwave
2016-12-31 16:00:40.198 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=204, service.id=331, service.bundleid=218, service.scope=bundle} - org.openhab.binding.zwave
2016-12-31 16:00:40.250 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2016-12-31 16:00:42.097 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2016-12-31 16:00:42.097 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller.
2016-12-31 16:00:42.114 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2016-12-31 16:00:42.122 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=334, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.124 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=335, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.142 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=336, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.151 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=337, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.152 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=338, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.159 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=339, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.186 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=340, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.246 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=341, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.260 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=342, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.287 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=343, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.288 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=344, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.291 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=345, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.306 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=346, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.326 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=347, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.343 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=348, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.350 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.370 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=349, service.bundleid=218, service.scope=singleton} - org.openhab.binding.zwave
2016-12-31 16:00:42.374 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.375 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.375 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.375 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.376 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.376 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.376 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.377 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.377 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.378 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.378 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.382 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-12-31 16:00:42.396 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:1587fb1d72a:node4:switch_binary --> REFRESH
2016-12-31 16:00:42.396 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2016-12-31 16:00:42.398 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:1587fb1d72a:node2:lock_door --> REFRESH
2016-12-31 16:00:42.398 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2016-12-31 16:00:42.398 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:1587fb1d72a:node2:battery-level --> REFRESH
2016-12-31 16:00:42.398 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2016-12-31 16:00:42.399 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:1587fb1d72a:node3:switch_binary --> REFRESH
2016-12-31 16:00:42.399 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.

So I really don’t know if this is OH2, Ubuntu, or an Aeon Gen 5 Controller issue.

On a side note. With all the recent changes in files/karaf being moved around. Where/how to start OH2 manually to see the console so I can confirm I do have the latest build?

[sihui]

@ptmuldoon

to see the console

ssh openhab@localhost -p 8101
password: habopen

No need to start openHAB manually.

You can also take a look at the version number if you open /userdata/etc/branding.properties:

\u001B[31m                         \u001B[0m __  _____    ____      \u001B[0m\r\n\
\u001B[31m  ____  ____  ___  ____  \u001B[0m/ / / /   |  / __ )     \u001B[0m\r\n\
\u001B[31m / __ \\/ __ \\/ _ \\/ __ \\\u001B[0m/ /_/ / /| | / __  | \u001B[0m\r\n\
\u001B[31m/ /_/ / /_/ /  __/ / / / \u001B[0m__  / ___ |/ /_/ /      \u001B[0m\r\n\
\u001B[31m\\____/ .___/\\___/_/ /_/\u001B[0m_/ /_/_/  |_/_____/     \u001B[0m\r\n\
\u001B[31m    /_/                       \u001B[0m 2.0.0-SNAPSHOT\u001B[0m\r\n\
\u001B[31m                              \u001B[0m Build #684   \u001B[0m\r\n\
\r\n\

[ptmuldoon (Paul Muldoon)]

In trying to resolve this, I did a complete purge and reinstall of OH2, and then added the user openhab to the dialout group as well.

I was able to set the binding to use /dev/ttyACM0 when first installing the binding. But now after a reboot, the Controller still shows as offline. I also do not have a lock file any longer in /var/lock so really have no idea why its not connecting.

This is the log info from OH2, and possibly still something with the serial binding? You can see the WARN info there.

2017-01-02 09:16:46.822 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-01-02 09:16:48.303 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-01-02 09:16:48.809 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-01-02 09:16:48.974 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2017-01-02 09:16:49.125 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2017-01-02 09:16:49.198 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.0.0.201701021217
2017-01-02 09:16:49.200 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2017-01-02 09:16:49.216 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=189, service.id=313, service.bundleid=202, service.scope=bundle} - org.openhab.binding.zwave
2017-01-02 09:16:49.345 [INFO ] [ding.astro.internal.bus.AstroBinding] - AstroConfig[latitude=42.898236,longitude=-78.6342,interval=43200,systemTimezone=America/New_York (EST -0500),daylightSavings=false]
2017-01-02 09:16:49.552 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=190, service.id=314, service.bundleid=202, service.scope=bundle} - org.openhab.binding.zwave
2017-01-02 09:16:49.663 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=192, service.id=315, service.bundleid=202, service.scope=bundle} - org.openhab.binding.zwave
2017-01-02 09:16:50.039 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-01-02 09:16:50.161 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-01-02 09:16:52.408 [INFO ] [ding.astro.internal.job.JobScheduler] - Scheduled a daily job at midnight for astro calculation
2017-01-02 09:16:52.986 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2017-01-02 09:16:52.986 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller.
2017-01-02 09:16:52.997 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2017-01-02 09:16:53.008 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=330, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.010 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=331, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.012 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=332, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.013 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=333, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.043 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=334, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.045 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=335, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.050 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=336, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.069 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=337, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.089 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=338, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.091 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=339, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.106 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=340, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.108 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=341, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.110 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=342, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.113 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=343, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.132 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=344, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.136 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=345, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.136 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.137 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: MANUFACTURER not set
2017-01-02 09:16:53.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.147 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.147 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.148 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.148 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.152 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.155 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2017-01-02 09:16:53.156 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-01-02 09:16:53.171 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-01-02 09:16:53.171 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2017-01-02 09:16:53.174 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-01-02 09:16:53.179 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2017-01-02 09:16:53.195 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-01-02 09:16:53.195 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-01-02 09:16:53.201 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Starting ZWave thread: Send
2017-01-02 09:16:53.204 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Activating ZWave discovery service for zwave:serial_zstick:1587fb1d72a
2017-01-02 09:16:53.205 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=346, service.bundleid=202, service.scope=singleton} - org.openhab.binding.zwave
2017-01-02 09:16:53.206 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting ZWave thread: Input
2017-01-02 09:16:53.678 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xFF.
2017-01-02 09:16:54.133 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x09.
2017-01-02 09:16:54.134 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2017-01-02 09:16:54.149 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x27.
2017-01-02 09:16:54.234 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xD2.
2017-01-02 09:16:54.757 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 01 01 01 
2017-01-02 09:16:54.757 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Message is invalid, discarding
2017-01-02 09:16:54.807 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:16:55.094 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:16:56.197 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2017-01-02 09:16:56.202 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-02 09:16:56.202 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2017-01-02 09:16:56.202 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2017-01-02 09:16:56.205 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
2017-01-02 09:16:56.207 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-02 09:16:56.208 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-01-02 09:16:56.210 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-01-02 09:16:56.211 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2017-01-02 09:16:56.211 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-01-02 09:16:56.658 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:16:57.502 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x04.
2017-01-02 09:16:58.123 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:17:01.207 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-02 09:17:01.208 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2017-01-02 09:17:01.208 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2017-01-02 09:17:01.208 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2017-01-02 09:17:01.208 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2017-01-02 09:17:01.792 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:02.533 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x33.
2017-01-02 09:17:02.538 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x39.
2017-01-02 09:17:02.544 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2017-01-02 09:17:02.545 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (153)
2017-01-02 09:17:02.545 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:17:02.545 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2017-01-02 09:17:02.573 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-02 09:17:02.573 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2017-01-02 09:17:02.573 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2017-01-02 09:17:02.574 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=GetVersion[0x15], type=Response[0x01], priority=High, dest=255, callback=0, payload=5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2017-01-02 09:17:02.580 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version = Z-Wave 3.95, Library Type = 0x01
2017-01-02 09:17:02.585 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=GetVersion[0x15], type=Request[0x00], priority=High, dest=255, callback=0, payload=
2017-01-02 09:17:02.586 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=GetVersion[0x15], type=Response[0x01], priority=High, dest=255, callback=0, payload=5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2017-01-02 09:17:02.593 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=GetVersion, callback id=0, expected=GetVersion, cancelled=false        transaction complete!
2017-01-02 09:17:02.593 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-01-02 09:17:02.594 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 1077ms/1077ms.
2017-01-02 09:17:02.594 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2017-01-02 09:17:02.594 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2017-01-02 09:17:02.594 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2017-01-02 09:17:07.596 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-02 09:17:07.597 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-01-02 09:17:07.597 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2017-01-02 09:17:07.597 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2017-01-02 09:17:07.597 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2017-01-02 09:17:08.259 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:17:08.263 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (232)
2017-01-02 09:17:08.263 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:17:08.291 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (0)
2017-01-02 09:17:08.542 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:12.991 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-02 09:17:12.991 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-01-02 09:17:12.991 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2017-01-02 09:17:12.991 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2017-01-02 09:17:12.991 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2017-01-02 09:17:18.146 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-02 09:17:18.147 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-01-02 09:17:18.147 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2017-01-02 09:17:18.148 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2017-01-02 09:17:18.148 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2017-01-02 09:17:18.774 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:20.540 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x07.
2017-01-02 09:17:20.541 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2017-01-02 09:17:20.566 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x03.
2017-01-02 09:17:23.513 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x07.
2017-01-02 09:17:23.513 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2017-01-02 09:17:23.521 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=MemoryGetId[0x20], type=Request[0x00], priority=High, dest=255, callback=0, payload=
2017-01-02 09:17:23.521 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-01-02 09:17:23.521 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2017-01-02 09:17:23.521 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2017-01-02 09:17:24.163 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x04.
2017-01-02 09:17:25.041 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:26.399 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:17:27.774 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:28.525 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-02 09:17:28.525 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-01-02 09:17:28.525 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-01-02 09:17:28.525 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2017-01-02 09:17:28.526 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2017-01-02 09:17:33.527 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-02 09:17:33.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-01-02 09:17:33.527 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-01-02 09:17:33.527 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2017-01-02 09:17:33.527 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2017-01-02 09:17:34.022 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2017-01-02 09:17:34.272 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:39.021 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-02 09:17:39.021 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-01-02 09:17:39.021 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-01-02 09:17:39.021 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2017-01-02 09:17:39.021 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2017-01-02 09:17:40.299 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (124)
2017-01-02 09:17:40.301 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 27 20 9A 41 B1 
2017-01-02 09:17:40.302 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Message is invalid, discarding
2017-01-02 09:17:40.802 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:41.981 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:44.025 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=SerialApiGetCapabilities[0x07], type=Request[0x00], priority=High, dest=255, callback=0, payload=
2017-01-02 09:17:44.025 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-01-02 09:17:44.025 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2017-01-02 09:17:44.026 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2017-01-02 09:17:44.287 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 04 13 01 01 
2017-01-02 09:17:44.287 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Message is invalid, discarding
2017-01-02 09:17:44.290 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x04.
2017-01-02 09:17:44.298 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xE8.
2017-01-02 09:17:44.302 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x04.
2017-01-02 09:17:44.553 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2017-01-02 09:17:44.972 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2017-01-02 09:17:45.506 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xAB.
2017-01-02 09:17:45.983 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x22.
2017-01-02 09:17:45.986 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2017-01-02 09:17:45.987 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x02.
2017-01-02 09:17:45.994 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x98.
2017-01-02 09:17:45.994 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x81.
2017-01-02 09:17:46.008 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x64.
2017-01-02 09:17:46.011 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xAB.
2017-01-02 09:17:46.012 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x68.
2017-01-02 09:17:46.017 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xF1.
2017-01-02 09:17:46.017 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x2A.
2017-01-02 09:17:46.017 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x40.
2017-01-02 09:17:46.018 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xD3.
2017-01-02 09:17:46.018 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xC4.
2017-01-02 09:17:46.018 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x78.
2017-01-02 09:17:46.018 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xA9.
2017-01-02 09:17:46.019 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xB6.
2017-01-02 09:17:46.019 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x44.
2017-01-02 09:17:46.019 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0xCF.
2017-01-02 09:17:46.020 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x65.
2017-01-02 09:17:49.029 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-02 09:17:49.029 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-01-02 09:17:49.029 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-01-02 09:17:49.029 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2017-01-02 09:17:49.030 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2017-01-02 09:17:54.376 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-02 09:17:54.376 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-01-02 09:17:54.377 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-01-02 09:17:54.377 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2017-01-02 09:17:54.377 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2017-01-02 09:17:59.748 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-02 09:17:59.748 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-01-02 09:17:59.748 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-01-02 09:17:59.748 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2017-01-02 09:17:59.748 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2017-01-02 09:18:04.757 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=SerialApiSetTimeouts[0x06], type=Request[0x00], priority=High, dest=255, callback=0, payload=96 0F 
2017-01-02 09:18:04.757 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-02 09:18:04.757 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2017-01-02 09:18:04.757 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2017-01-02 09:18:10.131 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-02 09:18:10.132 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-02 09:18:10.132 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-02 09:18:10.132 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2017-01-02 09:18:10.132 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2017-01-02 09:18:15.500 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-02 09:18:15.500 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-02 09:18:15.501 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-02 09:18:15.505 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2017-01-02 09:18:15.505 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2017-01-02 09:18:15.878 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 00 01 01 
2017-01-02 09:18:15.878 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Message is invalid, discarding
2017-01-02 09:18:15.887 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x56.
2017-01-02 09:18:18.574 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - ZWave product zwave:device has no references!
2017-01-02 09:18:18.575 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - ZWave product zwave:serial_zstick has no references!
2017-01-02 09:18:20.871 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-02 09:18:20.871 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-02 09:18:20.871 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-02 09:18:20.871 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2017-01-02 09:18:20.872 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2017-01-02 09:18:26.255 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=GetSucNodeId[0x56], type=Request[0x00], priority=High, dest=255, callback=0, payload=

[ptmuldoon (Paul Muldoon)]

Just an update and closing the loop on this.

I did a full, complete reinstall of Ubuntu 16 yesterday and then installed Java and OH2 and have had no issues with /dev/ttyACM0, the Zwave binding, and Aeon Gen 5 stick.

I can only guess something in my other Ubuntu VM had gone haywire blocking ACM0 from working although it was there and being forced to unplug and replug the device each time to use ACM1.

So, a fresh install of Ubuntu and no issues in 2 days after several reboots testing the VM.

[milty456 (Rich Smith)]

I did this as well 10 days ago…today, controller is not working again.

[milty456 (Rich Smith)]

any idea how to check if the controller is actually bound to acm0 in ubuntu?

[ptmuldoon (Paul Muldoon)]

@milty456

Can you give some background on your setup? Are you running Ubuntu in a Virtual Machine or on a physical box.

And what ZWave controller?

Did you add the user openhab todial out and tty groups?

http://docs.openhab.org/installation/linux.html#recommended-additional-setup-steps

[milty456 (Rich Smith)]

Ubuntu…on a odroid board with an EMMC(physical).

Aeon Labs zstick

Yeah, openhab is in the dialout group.
Not in the tty group

Anyway its working now and its not in the tty group.

Essentially the json db went corrupt…unsure why.
I had to readd the controller in paperui.

Thanks!