Z-wave initialization errors

markus7017 · December 26, 2016, 1:38pm

After moving from a running OH1 to a fresh OH2 installation (beta 5) I have strange problems with the z-wave devices (in total 25). I was able to install & configure the binding and the discovery brought up the devices. However a bunch fail to initialize (unknown device). Even a Figaro motion sensor and smoke detectors doesn’t get initialized (Node 4) as well as some of the roller shutters, whereas others work.

14:20:43.666 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.675 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:90fea84e:node4' to inbox.
14:20:43.677 [INFO ] [smarthome.event.InboxAddedEvent     ] - Discovery Result with UID 'zwave:device:90fea84e:node4' has been added.
14:20:43.687 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.716 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.763 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.774 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 17: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.782 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.790 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 19: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
14:20:43.817 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 25: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

I also get

14:36:39.918 [WARN ] [ve.internal.protocol.ZWaveController] - TODO: Implement processing of Request Message = -- (0x04)

Also multiple restarts of OH don’t solved the problem.

chris · December 26, 2016, 1:55pm

If the device type/id is still 7ffffff, then it means that the binding doesn’t have all the information about the device - ie initialisation isn’t complete.

However, the other warning is of more concern since I don’t know why this would happen. I would suggest to enable debug logging to try and find out what’s up.

markus7017 · December 27, 2016, 3:03pm

After another fresh-install with debugging enabled the “TODO: Implement processing of Request Message = – (0x04)” didn’t appeared again.

However, still having the problem that the Figaro motion sensor (Node 4) and the Smoke sensors (Node 16, 17, 18, 19) are not recognized even after OH is running for more than an hour:

2016-12-27 15:48:51.001 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: MANUFACTURER not set
2016-12-27 15:48:53.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2016-12-27 15:48:53.286 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 16: Init node thread start
2016-12-27 15:48:54.319 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 16: Serializing from file /usr/share/openhab2/userdata/zwave/node16.xml
2016-12-27 15:48:54.333 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 16: Error serializing from file: file does not exist.
2016-12-27 15:48:54.699 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Starting initialisation from EMPTYNODE
2016-12-27 15:48:54.740 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-12-27 15:48:54.937 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-12-27 15:48:54.938 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: Initialisation starting
2016-12-27 15:48:54.939 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to PROTOINFO
2016-12-27 15:48:54.941 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-12-27 15:48:54.942 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: PROTOINFO - send IdentifyNode
2016-12-27 15:48:54.945 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - queued packet. Queue length is 1
2016-12-27 15:48:54.960 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 16: Init node thread finished
2016-12-27 15:48:55.216 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: ProtocolInfo
2016-12-27 15:48:55.223 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Listening = false
2016-12-27 15:48:55.224 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Routing = true
2016-12-27 15:48:55.225 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Beaming = true
2016-12-27 15:48:55.226 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Version = 4
2016-12-27 15:48:55.228 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: FLIRS = false
2016-12-27 15:48:55.233 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Security = false
2016-12-27 15:48:55.248 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Max Baud = 40000
2016-12-27 15:48:55.251 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Basic = Routing Slave
2016-12-27 15:48:55.253 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Generic = Alarm Sensor
2016-12-27 15:48:55.255 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Specific = Routing Alarm Sensor
2016-12-27 15:48:55.259 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class NO_OPERATION
2016-12-27 15:48:55.261 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class NO_OPERATION, endpoint null created
2016-12-27 15:48:55.262 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Version = 1, version set. Enabling extra functionality.
2016-12-27 15:48:55.264 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class NO_OPERATION to the list of supported command classes.
2016-12-27 15:48:55.268 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class BASIC
2016-12-27 15:48:55.272 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class BASIC, endpoint null created
2016-12-27 15:48:55.275 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class BASIC to the list of supported command classes.
2016-12-27 15:48:55.280 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class SENSOR_ALARM
2016-12-27 15:48:55.284 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class SENSOR_ALARM, endpoint null created
2016-12-27 15:48:55.287 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class SENSOR_ALARM to the list of supported command classes.
2016-12-27 15:48:55.291 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-12-27 15:48:55.295 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class MANUFACTURER_SPECIFIC, endpoint null created
2016-12-27 15:48:55.298 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes.
2016-12-27 15:48:55.301 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class BATTERY
2016-12-27 15:48:55.305 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class BATTERY, endpoint null created
2016-12-27 15:48:55.309 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class BATTERY to the list of supported command classes.
2016-12-27 15:48:55.312 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class ASSOCIATION
2016-12-27 15:48:55.316 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class ASSOCIATION, endpoint null created
2016-12-27 15:48:55.320 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class ASSOCIATION to the list of supported command classes.
2016-12-27 15:48:55.323 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class VERSION
2016-12-27 15:48:55.327 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class VERSION, endpoint null created
2016-12-27 15:48:55.331 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Adding command class VERSION to the list of supported command classes.
2016-12-27 15:48:55.352 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-12-27 15:48:55.355 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - checking initialisation queue. Queue size 1.
2016-12-27 15:48:55.359 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - message removed from queue. Queue size 0.
2016-12-27 15:48:55.363 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-12-27 15:48:55.368 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-12-27 15:48:55.372 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to INIT_NEIGHBORS
2016-12-27 15:48:55.379 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - INIT_NEIGHBORS try 0: stageAdvanced(true)
2016-12-27 15:48:55.382 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: INIT_NEIGHBORS - send RoutingInfo
2016-12-27 15:48:55.387 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 16: Request routing info
2016-12-27 15:48:55.391 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - queued packet. Queue length is 1
2016-12-27 15:48:58.953 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 16: Got NodeRoutingInfo request.
2016-12-27 15:48:58.988 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 16: Neighbor nodes: 1 6 7 8 10 11 12 13 14 15 20 21 23 24
2016-12-27 15:48:59.004 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - INIT_NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-12-27 15:48:59.004 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - checking initialisation queue. Queue size 1.
2016-12-27 15:48:59.005 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - message removed from queue. Queue size 0.
2016-12-27 15:48:59.005 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - INIT_NEIGHBORS: queue length(0), free to send(true)
2016-12-27 15:48:59.005 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - INIT_NEIGHBORS try 1: stageAdvanced(false)
2016-12-27 15:48:59.006 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to FAILED_CHECK
2016-12-27 15:48:59.007 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-12-27 15:48:59.008 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 16: Requesting IsFailedNode status from controller.
2016-12-27 15:48:59.010 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - queued packet. Queue length is 1
2016-12-27 15:48:59.203 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller status changed to ONLINE.
2016-12-27 15:48:59.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller is ONLINE. Starting device initialisation.
2016-12-27 15:48:59.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties.
2016-12-27 15:48:59.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties. MAN=2147483647
2016-12-27 15:48:59.208 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising Thing Node...
2016-12-27 15:48:59.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
2016-12-27 15:49:01.614 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 16: Is currently marked as healthy by the controller
2016-12-27 15:49:01.638 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2016-12-27 15:49:01.638 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - checking initialisation queue. Queue size 1.
2016-12-27 15:49:01.642 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - message removed from queue. Queue size 0.
2016-12-27 15:49:01.645 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2016-12-27 15:49:01.647 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2016-12-27 15:49:01.650 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to WAIT
2016-12-27 15:49:01.655 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-12-27 15:49:01.657 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2016-12-27 15:49:01.660 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2016-12-27 15:49:01.663 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: WAIT - Still waiting!
2016-12-27 15:52:20.575 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - WAIT: The WAIT is over!
2016-12-27 15:52:20.575 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - checking initialisation queue. Queue size 0.

whereas the same smoke detector (Node 5 - same device type) gets initialized.

2016-12-27 15:48:51.166 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:a839a5e4:node5:sensor_temperature --> REFRESH
2016-12-27 15:48:51.169 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:a839a5e4:node5:battery-level --> REFRESH
2016-12-27 15:48:51.172 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:a839a5e4:node5:alarm_smoke --> REFRESH
2016-12-27 15:48:51.175 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:a839a5e4:node5:alarm_general --> REFRESH
2016-12-27 15:48:51.178 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:a839a5e4:node5:alarm_heat --> REFRESH
2016-12-27 15:48:53.119 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2016-12-27 15:48:53.202 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Init node thread start
2016-12-27 15:48:54.319 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 5: Serializing from file /usr/share/openhab2/userdata/zwave/node5.xml
2016-12-27 15:48:55.009 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Restore from config: Ok.
2016-12-27 15:48:55.028 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from EMPTYNODE
2016-12-27 15:48:55.038 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-12-27 15:48:55.041 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-12-27 15:48:55.130 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: Initialisation starting
2016-12-27 15:48:55.131 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - advancing to PROTOINFO
2016-12-27 15:48:55.137 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-12-27 15:48:55.179 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: PROTOINFO - send IdentifyNode
2016-12-27 15:48:55.181 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - queued packet. Queue length is 1
2016-12-27 15:48:55.184 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery completed
2016-12-27 15:48:57.734 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Checking zwave:fibaro_fgss001_00_000
2016-12-27 15:48:57.735 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery resolved to thingType zwave:fibaro_fgss001_00_000
2016-12-27 15:48:57.738 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from EMPTYNODE
2016-12-27 15:48:57.745 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - EMPTYNODE: queue length(1), free to send(false)
2016-12-27 15:48:57.747 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - queued packet. Queue length is 1
2016-12-27 15:48:57.752 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Init node thread finished
2016-12-27 15:48:57.799 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: ProtocolInfo
2016-12-27 15:48:57.800 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Listening = false
2016-12-27 15:48:57.802 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Routing = true
2016-12-27 15:48:57.803 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Beaming = true
2016-12-27 15:48:57.804 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Version = 4
2016-12-27 15:48:57.805 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: FLIRS = false
2016-12-27 15:48:57.805 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Security = false
2016-12-27 15:48:57.805 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Max Baud = 40000
2016-12-27 15:48:57.806 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Basic = Routing Slave
2016-12-27 15:48:57.806 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Generic = Alarm Sensor
2016-12-27 15:48:57.807 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Specific = Routing Alarm Sensor
2016-12-27 15:48:57.808 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Creating new instance of command class NO_OPERATION
2016-12-27 15:48:57.809 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Command class NO_OPERATION, endpoint null created

After initialization the is a node5.xml in the wave directory, but no node16.xml 17,18,19.xml

chris · December 27, 2016, 4:34pm

Time won’t help you I’m afraid. You must wake the device up manually so that it can complete initialisation. Once initialisation is completed, the device will hopefully be configured to wake up itself every hour or so, but until then, it won’t do much.

You need to do this in close proximity to the controller - mesh networking wont work for the first initialisation as some commands are not routable.