Thank you. I’ve been doing all of that as well, but I’ll keep trying!
Seeing the same thing with one of my nodes. Controller says its offline, but all communication from the node to openHAB works fine. When new events come in, the node goes to online, but then switches back to offline because that is what they controller thinks.
Is it a battery device, or mains device?
Just discovered another minor issue.
One node (out of 30+) is acting a bit strange, or rather the log is. Node works fine.
Prior to switching to new test binding, my node 28 was defined by this line in my .items file:
Switch FanS1 "Vifte av/1" <fan> (div, switches) { channel = "zwave:device:3f5c8071:node28:switch_binary" }
After re-adding items in Paper UI the new network ID became:
Switch FanS1 "Vifte av/1" <fan> (div, switches) { channel = "zwave:device:15b9cb3d46b:node28:switch_binary" }
In Eclipse Smarthome Designer I did a global search & replace in my .items file: 3f5c8071 -> 15b9cb3d46b and saved.
Now, when operating node 28, it switches fine, but the following lines appear in the log:
2017-04-24 21:09:40.450 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate command 'ON' for item 'FanS1' to handler for channel 'zwave:device:3f5c8071:node28:switch_binary', because no thing with the UID 'zwave:device:3f5c8071:node28' could be found.
As you see, the old network ID is still referred to by ‘something’. 
Not a big deal for me, but it might tell you @chris something?
@OMR - I had this problem originally when I had to fully reset my ZWave network. You will likely start to see these messages more often than you think for other devices occasionally.
I’m not sure what triggers or fully connects it to show, but I’d imagine if you try to use the karaf console and use the links:list command, you will find that most all of your devices have more than one link. One to the new device, one to the old. (aka the ZWave network ID).
Couple ways to go about fixing, but I’ll leave to you. API is one way, could make it easy to script removal of all the items after doing a get. Could go through individually using Karaf to remove the links. Maybe other ways as well. But I’d imagine this is going to resolve those messages.
1 Like
These aren’t allocated at all in the zwave binding…
My guess is that this isn’t anything to do with the zwave binding. It looks like something somewhere in the definitions is still saving the old UID - possibly in the jsondb files?
Mains, it’s a CT100 stat
Had 4 references to old network ID:
openhab> links list | grep 3f5c
FanS1 -> zwave:device:3f5c8071:node28:switch_binary
div -> zwave:device:3f5c8071:node23:switch_binary
div -> zwave:device:3f5c8071:node23:switch_binary1
div -> zwave:device:3f5c8071:node23:switch_binary2
Removed by:
openhab> links removeChannelLink FanS1 zwave:device:3f5c8071:node28:switch_binary
Link FanS1 -> zwave:device:3f5c8071:node28:switch_binarysuccessfully removed.
openhab> links removeChannelLink div zwave:device:3f5c8071:node23:switch_binary
Link div -> zwave:device:3f5c8071:node23:switch_binarysuccessfully removed.
openhab> links removeChannelLink div zwave:device:3f5c8071:node23:switch_binary1
Link div -> zwave:device:3f5c8071:node23:switch_binary1successfully removed.
openhab> links removeChannelLink div zwave:device:3f5c8071:node23:switch_binary2
Link div -> zwave:device:3f5c8071:node23:switch_binary2successfully removed.
openhab> links list | grep 3f5c
openhab>
WARN log entries now gone.
So I learned something new today (also) 
Thanks @shawnmix & @chris
This. Removing via paperui didn’t delete my lock from the persistence layer (json) so I manually deleted them with a text editor and it’s been fine.
@chris
Hi Chris, i still get these in my log:
2017-04-25 10:35:59.795 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling...
2017-04-25 10:35:59.800 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:374)[198:org.openhab.binding.zwave:2.1.0.201704232237]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Do you perhaps know what causing this?
And what is Node 0?
br,
Raymond
It will probably be associated with the node 0 statement. Probably somewhere something isn’t configured correctly. Maybe there’s a node that is still in the database that has some old settings from the old version of the binding where node ids were in properties (and they are now in configuration).
I would take a look at the binding startup to see if there are any errors there?
Hi.
I have another question about nodes being marked as failed. I just updated my binding to the latest one (thus also restarting the binding). Before that all my nodes were online and working. Now the log tells me every 30 seconds that two of my nodes are “currently marked as failed by the controller”.
Questions:
- Is this really the controller saying they’re failed? Why would the controller suddenly mark nodes as failed because I restart the binding?
- Do we really need this printed out in the log this often? It’s totally spamming my log. Is this because it tries to reason with the nodes every 30 seconds?
edit: After some debug logging I realize this is because the binding is requesting the IsFailedNode status every 30 seconds. Still don’t understand why they’re failed though…
Yes - this comes directly from the controller.
Why not? The controller is totally autonomous and separate from the binding. If it’s plugged in to the PC, it can still do things on the network to maintain the system.
Well, that’s how it is at the moment - you are running test software so I have a lot of debug messages to support testing.
Here is a piece of the log right after i restarted the zwave-binding:
2017-04-25 10:49:21.813 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STOPPING - org.openhab.binding.zwave
2017-04-25 10:49:21.847 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=228, service.id=439, service.bundleid=198, service.scope=bundle} - org.openhab.binding.zwave
2017-04-25 10:49:21.862 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=229, service.id=440, service.bundleid=198, service.scope=bundle} - org.openhab.binding.zwave
2017-04-25 10:49:21.877 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=232, service.id=441, service.bundleid=198, service.scope=bundle} - org.openhab.binding.zwave
2017-04-25 10:49:21.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:21.946 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 11: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_11.xml
2017-04-25 10:49:21.979 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=443, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:21.984 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.021 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 10: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_10.xml
2017-04-25 10:49:22.066 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=445, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.070 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.097 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 28: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_28.xml
2017-04-25 10:49:22.138 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=449, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.143 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.171 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 29: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_29.xml
2017-04-25 10:49:22.207 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=455, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.233 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 6: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_6.xml
2017-04-25 10:49:22.255 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=450, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.262 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.284 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 24: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_24.xml
2017-04-25 10:49:22.309 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=444, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.333 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 25: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_25.xml
2017-04-25 10:49:22.356 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=456, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.360 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.384 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 12: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_12.xml
2017-04-25 10:49:22.407 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=451, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.453 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 7: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_7.xml
2017-04-25 10:49:22.482 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=447, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.515 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 13: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_13.xml
2017-04-25 10:49:22.542 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=454, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.546 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.577 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 5: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_5.xml
2017-04-25 10:49:22.613 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=446, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.619 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.643 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 14: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_14.xml
2017-04-25 10:49:22.662 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=453, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.666 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.683 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 4: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_4.xml
2017-04-25 10:49:22.701 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=452, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.704 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.726 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 9: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_9.xml
2017-04-25 10:49:22.743 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=448, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.746 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2017-04-25 10:49:22.765 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 30: Serializing to file /var/lib/openhab2/zwave/network_014cfbba__node_30.xml
2017-04-25 10:49:22.782 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=457, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:22.990 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2017-04-25 10:49:26.001 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2017-04-25 10:49:26.006 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Deactivating ZWave discovery service for zwave:serial_zstick:126c07f3
2017-04-25 10:49:26.019 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=442, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:26.498 [DEBUG] [inding.zwave.internal.ZWaveActivator] - ZWave binding stopped.
2017-04-25 10:49:26.501 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STOPPED - org.openhab.binding.zwave
2017-04-25 10:49:26.503 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STARTING - org.openhab.binding.zwave
2017-04-25 10:49:26.505 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.1.0.201704232237
2017-04-25 10:49:26.563 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STARTED - org.openhab.binding.zwave
2017-04-25 10:49:26.661 [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=233, service.id=459, service.bundleid=198, service.scope=bundle} - org.openhab.binding.zwave
2017-04-25 10:49:26.673 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=234, service.id=460, service.bundleid=198, service.scope=bundle} - org.openhab.binding.zwave
2017-04-25 10:49:26.693 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=237, service.id=461, service.bundleid=198, service.scope=bundle} - org.openhab.binding.zwave
2017-04-25 10:49:29.475 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2017-04-25 10:49:29.480 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:126c07f3.
2017-04-25 10:49:29.484 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 16 hours time.
2017-04-25 10:49:29.495 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB-AeonLabs-ZStick'
2017-04-25 10:49:29.504 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2017-04-25 10:49:29.506 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-04-25 10:49:29.506 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2017-04-25 10:49:29.507 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2017-04-25 10:49:29.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-25 10:49:29.510 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-04-25 10:49:29.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-25 10:49:29.511 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-04-25 10:49:29.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-25 10:49:29.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-04-25 10:49:29.513 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2017-04-25 10:49:29.514 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Activating ZWave discovery service for zwave:serial_zstick:126c07f3
2017-04-25 10:49:29.521 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=462, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.524 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 21
2017-04-25 10:49:29.555 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=463, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.556 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=465, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.557 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=466, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.555 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=464, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.561 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=467, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.728 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=468, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.749 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=469, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.758 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=470, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.775 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=471, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.821 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=476, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.822 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=475, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.823 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=472, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.823 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=473, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.823 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=474, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.875 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=477, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2017-04-25 10:49:29.875 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node10.
2017-04-25 10:49:29.879 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node25.
2017-04-25 10:49:29.882 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node24.
2017-04-25 10:49:29.885 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node12.
2017-04-25 10:49:29.886 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node7.
2017-04-25 10:49:29.890 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node11.
2017-04-25 10:49:29.893 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node5.
2017-04-25 10:49:29.895 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node13.
2017-04-25 10:49:29.897 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node14.
2017-04-25 10:49:29.899 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node9.
2017-04-25 10:49:29.899 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node30.
2017-04-25 10:49:29.902 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node28.
2017-04-25 10:49:29.904 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node4.
2017-04-25 10:49:29.913 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node6.
2017-04-25 10:49:29.921 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:126c07f3:node29.
2017-04-25 10:49:32.513 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2017-04-25 10:49:32.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-04-25 10:49:32.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-04-25 10:49:32.551 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-25 10:49:32.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-25 10:49:32.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-04-25 10:49:32.557 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
2017-04-25 10:49:32.560 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
2017-04-25 10:49:32.573 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-25 10:49:32.576 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2348: Transaction Start type GetVersion
2017-04-25 10:49:32.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2348: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-04-25 10:49:32.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-04-25 10:49:32.582 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-25 10:49:32.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-04-25 10:49:32.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-25 10:49:32.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-04-25 10:49:32.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-25 10:49:32.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Apr 25 10:49:34 CEST 2017 - 1988ms
2017-04-25 10:49:32.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-25 10:49:32.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-04-25 10:49:32.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 2348: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-04-25 10:49:32.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-04-25 10:49:32.621 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-25 10:49:32.623 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B
2017-04-25 10:49:32.623 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-25 10:49:32.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-25 10:49:32.633 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-25 10:49:32.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-25 10:49:32.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Apr 25 10:49:34 CEST 2017 - 1963ms
2017-04-25 10:49:32.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=GetVersion[0x15], type=Response[0x01], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 32 2E 37 38 00 01
2017-04-25 10:49:32.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-04-25 10:49:32.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-25 10:49:32.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-04-25 10:49:32.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Apr 25 10:49:34 CEST 2017 - 1954ms
2017-04-25 10:49:32.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=GetVersion[0x15], type=Response[0x01], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 32 2E 37 38 00 01
2017-04-25 10:49:32.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-25 10:49:32.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-25 10:49:32.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-25 10:49:32.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=GetVersion[0x15], type=Response[0x01], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 32 2E 37 38 00 01
2017-04-25 10:49:32.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Apr 25 10:49:34 CEST 2017 - 1947ms
2017-04-25 10:49:32.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2348: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-04-25 10:49:32.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-04-25 10:49:32.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 2
2017-04-25 10:49:32.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-25 10:49:32.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-04-25 10:49:32.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2348: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-04-25 10:49:32.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-25 10:49:32.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-25 10:49:32.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Apr 25 10:49:34 CEST 2017 - 1942ms
2017-04-25 10:49:32.658 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[0x15], type=Response[0x01], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 32 2E 37 38 00 01
2017-04-25 10:49:32.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-04-25 10:49:32.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 3
2017-04-25 10:49:32.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-25 10:49:32.659 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version = Z-Wave 2.78, Library Type = 0x01
2017-04-25 10:49:32.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-25 10:49:32.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-25 10:49:32.660 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2348: Transaction COMPLETED
So you are saying that because the controller is autonomous it just happened to mark two nodes as failed exactly when I was doing a restart of the binding? I’m sorry, but that seems like too much of a coincidence to me…
I don’t know - all I’m saying is that the information comes from the controller, and the controller isn’t just doing things when the binding is running. What the controller actually does I can’t comment on. I personally don’t understand why it’s marking devices as failed at all, but all I’ve got to go on is the documents I have.
What do you propose?
Unfortunately after running one night in my production environment there are again java exceptions in Karaf:
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommand
Class.handleApplicationCommandRequest(ZWaveCommandClass.java:245)
at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(
ZWaveNode.java:1284)
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$Z
WaveReceiveThread.run(ZWaveTransactionManager.java:413)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 3
at org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload.
getPayloadByte(ZWaveCommandClassPayload.java:49)
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLe
velSwitchCommandClass.handleSwitchMultilevelSupportedReport(ZWaveMultiLevelSwitc
hCommandClass.java:112)
... 7 more
I am using Zwave Binding 2.1.0.201704232237.
Is there any way to see the timestamp of the java exceptions in any log? At the moment I can hardly tell what the cause is as I only find the exceptions without timestamp in karaf log.
Nothing really. Just trying to wrap my head around this. I’ve been running OH now for some months and before that I used openzwave for some years and with both softwares the big problem has always been nodes being marked as failed. Am I the only one or is this a general problem? If it’s only me I’m thinking simply my controller (a Aeon z-stick gen1) is not healthy.
Well, the way this binding works is totally different to OH1, and the current stable OH2 (as said, it’s a test binding). In the old system, I kept my own state as to a device being DEAD or ALIVE based on responses. Retries etc were then based on this, but unlike OZW we always send data to a device (I saw a request recently in the OZW list that requested to change OZW to do the same as I implemented in OH).
For this binding, I thought that the controller probably has the best view about the state of a device, so I decided to simplify things by using the controllers FAILED flag instead of maintaining my own flag. My view was that the controller has a lot more information about what is happening at the lower layers, and therefore should have a better status. This might be wrong… As I said, this is test software, so you’re all guinea pigs ;). As the documentation I have for these APIs is very old, some things have to be a little trial and error.
I think that was actually me talking, shortly before I gave up on OZW 
Thing is, I can’t possibly believe the “real” licensed controllers have these problems, so obviously there’s a way to solve it and not a flaud in the protocol as such. I mean, all that would really be needed would be a way for the binding to tell the controller that “I know this node is alive so could you please mark it as such”, wouldn’t it? One would hope that now that Sigma actually released parts of the specs to the public they would also be friendly enough to help out with problems like this…
edit: Just to be clear, I agree that the way things look currently (ie we can’t affect the controllers FAILED flag) there is no point in maintaining an own flag of the same kind, since it doesn’t matter what we think about the nodes status. If the controller has marked it as FAILED we can’t talk to it anyway…