No XML file created for new device

RayBe · March 8, 2017, 10:50am

Hi Guys,

I have a Remotec Z-URC 550EU remote that i would like to add to the Z-Wave database.
Paper UI recognized it as:
Z-Wave Node 2 (5254:0000:5320:0.0)
There is no XML-file created for the device.
What can i do to get a XML-file created so that i can add it to the database?
Thanks upfront,

br,
Raymond

chris · March 8, 2017, 12:07pm

You should capture a debug log so we can work out why it’s not completing initialisation. It’s possible that the binding is stuck trying to get some information that the device is not providing - we need to identify if this is the case and the debug log is the best way to do this.

RayBe · March 8, 2017, 2:31pm

From my openhab.log after restarting my OpenHAB2 server:

2017-03-08 15:03:38.373 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-03-08 15:03:38.374 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-03-08 15:03:39.197 [INFO ] [b.core.service.AbstractActiveService] - FritzboxTr064 Refresh Service has been started
2017-03-08 15:03:39.337 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-03-08 15:03:39.430 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-03-08 15:03:41.572 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-03-08 15:03:41.574 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-03-08 15:03:41.575 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2017-03-08 15:03:41.576 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2017-03-08 15:03:41.577 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found
2017-03-08 15:03:41.578 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2017-03-08 15:03:41.579 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2017-03-08 15:03:41.580 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 11: Node found
2017-03-08 15:03:41.581 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2017-03-08 15:03:41.582 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2017-03-08 15:03:41.583 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2017-03-08 15:03:41.583 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2017-03-08 15:03:41.584 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2017-03-08 15:03:41.585 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2017-03-08 15:03:41.585 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2017-03-08 15:03:41.586 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 19: Node found
2017-03-08 15:03:41.587 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-03-08 15:03:41.588 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-03-08 15:03:41.589 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-03-08 15:03:41.590 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 16
2017-03-08 15:03:41.591 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-03-08 15:03:43.022 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery could not resolve to a thingType! 0001:5257:3330::1.10
2017-03-08 15:04:23.746 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2017-03-08 15:04:23.810 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery could not resolve to a thingType! 0001:5257:3330::1.10
2017-03-08 15:04:23.821 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 17: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2017-03-08 15:04:57.709 [WARN ] [essage.ApplicationUpdateMessageClass] - TODO: Implement Application Update Request Handling of SUC ID (16).

chris · March 8, 2017, 2:38pm

A debug level log is really needed - this doesn’t really provide any useful information. The documentation will tell you how to enable debugging logging if you’re unsure.

RayBe · March 9, 2017, 1:19pm

After i did another search for things and put the remote in listening mode, the log shows:

14:00:36.195 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 5254:0000:5320::1.3
14:00:36.197 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - DISCOVERY_COMPLETE try 0: stageAdvanced(true)
14:00:36.197 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Serialise aborted as static stages not complete
14:00:36.197 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to VERSION
14:00:36.197 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
14:00:36.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - VERSION try 0: stageAdvanced(true)
14:00:36.201 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - thing is null!
14:00:36.201 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking BASIC, version is 0
14:00:36.202 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   BASIC
14:00:36.202 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class BASIC
14:00:36.202 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
14:00:36.203 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
14:00:36.203 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking MANUFACTURER_SPECIFIC, version is 0
14:00:36.203 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   MANUFACTURER_SPECIFIC
14:00:36.203 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class MANUFACTURER_SPECIFIC
14:00:36.203 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking SCENE_CONTROLLER_CONF, version is 0
14:00:36.204 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   SCENE_CONTROLLER_CONF
14:00:36.204 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class SCENE_CONTROLLER_CONF
14:00:36.204 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking NO_OPERATION, version is 1
14:00:36.204 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking WAKE_UP, version is 0
14:00:36.205 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   WAKE_UP
14:00:36.205 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class WAKE_UP
14:00:36.205 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking VERSION, version is 0
14:00:36.205 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   VERSION
14:00:36.205 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class VERSION
14:00:36.206 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking ASSOCIATION, version is 0
14:00:36.206 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   ASSOCIATION
14:00:36.206 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class ASSOCIATION
14:00:36.207 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking CONTROLLER_REPLICATION, version is 0
14:00:36.207 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   CONTROLLER_REPLICATION
14:00:36.207 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class CONTROLLER_REPLICATION
14:00:36.207 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued 7 frames
14:00:36.208 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:36.208 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 291ms/2544ms.
14:00:36.208 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 04 02 02 84 07 74 
14:00:36.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 04 02 02 84 07 74 
14:00:36.210 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=04 02 02 84 07 
14:00:36.210 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:VERSION)
14:00:36.210 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class WAKE_UP
14:00:36.211 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Received Wake Up Request
14:00:36.211 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Received WAKE_UP_NOTIFICATION
14:00:36.211 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is awake with 0 messages in the wake-up queue.
14:00:36.211 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
14:00:36.212 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Wakeup during initialisation.
14:00:36.212 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - VERSION: queue length(7), free to send(false)
14:00:36.212 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 7
14:00:36.213 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
14:00:36.213 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=152, payload=02 02 86 11 
14:00:36.214 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=04 02 02 84 07 
14:00:36.214 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=152, expected=ApplicationCommandHandler, cancelled=true      MISMATCH
14:00:36.215 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
14:00:36.216 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 86 11 25 98 CF 
14:00:36.217 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 86 11 25 98 CF 
14:00:36.225 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
14:00:36.227 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:36.227 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
14:00:36.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
14:00:36.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
14:00:36.228 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
14:00:36.352 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 07 86 12 02 02 4E 01 03 2B 
14:00:36.356 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:36.358 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 02 07 86 12 02 02 4E 01 03 2B 
14:00:36.359 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 02 07 86 12 02 02 4E 01 03 2B 
14:00:36.360 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 02 02 4E 01 03 
14:00:36.360 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:VERSION)
14:00:36.360 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class VERSION
14:00:36.360 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Received COMMAND_CLASS_VERSION command V0
14:00:36.360 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Process Version Report
14:00:36.361 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Library Type        = 2 (Controller)
14:00:36.361 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Protocol Version    = 2.78
14:00:36.361 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Application Version = 1.3
14:00:36.362 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=152, payload=02 02 86 11 
14:00:36.362 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 86 12 02 02 4E 01 03 
14:00:36.362 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=152, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
14:00:36.363 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
14:00:36.363 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - VERSION: Transaction complete (SendData:Request) success(true)
14:00:36.363 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 7.
14:00:36.364 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 146ms/2544ms.
14:00:36.364 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
14:00:36.366 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 86 13 20 25 9A ED 
14:00:36.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 86 13 20 25 9A ED 
14:00:36.373 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
14:00:36.374 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:36.375 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
14:00:36.375 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
14:00:36.375 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
14:00:36.376 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
14:00:36.429 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 9A 00 73 
14:00:36.430 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:36.431 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 13 9A 00 00 00 71 
14:00:36.431 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 13 9A 00 00 00 71 
14:00:36.432 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9A 00 
14:00:36.432 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 154, Status = Transmission complete and ACK received(0)
14:00:36.432 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=154, payload=02 03 86 13 20 
14:00:36.433 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9A 00 
14:00:36.433 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=154, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
14:00:36.441 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 9A 00 73 
14:00:36.442 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:36.443 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 13 9A 00 00 00 71 
14:00:36.444 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 13 9A 00 00 00 71 
14:00:36.445 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9A 00 
14:00:36.445 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 154, Status = Transmission complete and ACK received(0)
14:00:36.446 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=154, payload=02 03 86 13 20 
14:00:36.447 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9A 00 
14:00:36.447 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=154, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
14:00:41.368 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
14:00:41.369 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is sleeping
14:00:41.369 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Putting message SendData in wakeup queue.
14:00:41.370 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
14:00:41.370 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Message already on the wake-up queue. Removing original.
14:00:41.371 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Putting message SendData in wakeup queue.
14:00:47.109 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 04 02 02 84 07 74 
14:00:47.120 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:47.123 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 04 02 02 84 07 74 
14:00:47.125 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 04 02 02 84 07 74 
14:00:47.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=04 02 02 84 07 
14:00:47.129 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:VERSION)
14:00:47.133 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class WAKE_UP
14:00:47.134 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Received Wake Up Request
14:00:47.135 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Received WAKE_UP_NOTIFICATION
14:00:47.136 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 2: Is awake with 1 messages in the wake-up queue.
14:00:47.137 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
14:00:47.138 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Wakeup during initialisation.
14:00:47.139 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - VERSION: queue length(7), free to send(false)
14:00:47.140 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - VERSION try 1: stageAdvanced(false)
14:00:47.148 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - thing is null!
14:00:47.149 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking BASIC, version is 0
14:00:47.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   BASIC
14:00:47.151 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class BASIC
14:00:47.153 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
14:00:47.155 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
14:00:47.155 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
14:00:47.156 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking MANUFACTURER_SPECIFIC, version is 0
14:00:47.157 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   MANUFACTURER_SPECIFIC
14:00:47.158 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class MANUFACTURER_SPECIFIC
14:00:47.159 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 86 13 20 25 9B EC 
14:00:47.161 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 86 13 20 25 9B EC 
14:00:47.161 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking SCENE_CONTROLLER_CONF, version is 0
14:00:47.163 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   SCENE_CONTROLLER_CONF
14:00:47.164 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class SCENE_CONTROLLER_CONF
14:00:47.166 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking NO_OPERATION, version is 1
14:00:47.168 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking WAKE_UP, version is 0
14:00:47.169 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   WAKE_UP
14:00:47.170 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
14:00:47.170 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class WAKE_UP
14:00:47.173 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking VERSION, version is 0
14:00:47.174 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   VERSION
14:00:47.175 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class VERSION
14:00:47.177 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking ASSOCIATION, version is 0
14:00:47.179 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   ASSOCIATION
14:00:47.180 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class ASSOCIATION
14:00:47.181 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 9B 00 72 
14:00:47.181 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - checking CONTROLLER_REPLICATION, version is 0
14:00:47.182 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued   CONTROLLER_REPLICATION
14:00:47.182 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Creating new message for application command VERSION_COMMAND_CLASS_GET command class CONTROLLER_REPLICATION
14:00:47.182 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: VERSION - queued 7 frames
14:00:47.182 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
14:00:47.183 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=156, payload=02 03 86 13 20 
14:00:47.183 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
14:00:47.184 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
14:00:47.184 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
14:00:47.184 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
14:00:47.185 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
14:00:47.185 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:47.185 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 13 9B 00 00 00 70 
14:00:47.186 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 13 9B 00 00 00 70 
14:00:47.186 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9B 00 
14:00:47.186 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 155, Status = Transmission complete and ACK received(0)
14:00:47.187 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=155, payload=02 03 86 13 20 
14:00:47.187 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9B 00 
14:00:47.187 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=155, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
14:00:47.237 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 04 86 14 20 00 45 
14:00:47.239 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:47.240 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 02 04 86 14 20 00 45 
14:00:47.240 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 02 04 86 14 20 00 45 
14:00:47.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 04 86 14 20 00 
14:00:47.241 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:VERSION)
14:00:47.241 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class VERSION
14:00:47.242 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Received COMMAND_CLASS_VERSION command V0
14:00:47.242 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Process Version Command Class Report
14:00:47.242 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Requested Command Class = BASIC, Version = 0
14:00:47.242 [INFO ] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Command Class BASIC has version 0!
14:00:47.243 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Version = 1, version set. Enabling extra functionality.
14:00:47.243 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=155, payload=02 03 86 13 20 
14:00:47.243 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 04 86 14 20 00 
14:00:47.244 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=155, expected=ApplicationCommandHandler, cancelled=false        transaction complete!
14:00:47.244 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
14:00:47.244 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - VERSION: Transaction complete (SendData:Request) success(true)
14:00:47.244 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 7.
14:00:47.245 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 6.
14:00:47.245 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - VERSION: queue length(6), free to send(true)
14:00:47.245 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 6
14:00:47.245 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
14:00:47.246 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 84ms/2544ms.
14:00:47.246 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
14:00:47.247 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 86 13 20 25 9C EB 
14:00:47.248 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 86 13 20 25 9C EB 
14:00:47.255 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
14:00:47.257 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:47.257 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
14:00:47.257 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
14:00:47.258 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
14:00:47.258 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
14:00:47.267 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 9C 00 75 
14:00:47.268 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:47.269 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 13 9C 00 00 00 77 
14:00:47.269 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 13 9C 00 00 00 77 
14:00:47.270 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9C 00 
14:00:47.270 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 156, Status = Transmission complete and ACK received(0)
14:00:47.270 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=2, callback=156, payload=02 03 86 13 20 
14:00:47.271 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9C 00 
14:00:47.271 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=156, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
14:00:48.810 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 04 86 14 20 00 45 
14:00:48.813 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
14:00:48.817 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 02 04 86 14 20 00 45 
14:00:48.820 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 02 04 86 14 20 00 45 
14:00:48.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 04 86 14 20 00 
14:00:48.825 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:VERSION)
14:00:48.826 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class VERSION
14:00:48.828 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Received COMMAND_CLASS_VERSION command V0
14:00:48.829 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Process Version Command Class Report
14:00:48.830 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 2: Requested Command Class = BASIC, Version = 0

hope this helps,

br,
Raymond

chris · March 15, 2017, 6:36pm

Sorry - I missed this (it’s best to use the Reply button at the bottom of my previous message than the one at the bottom of the page. If you use the one at the bottom of the page, then the forum won’t give me a notification that there’s a message for me…).

Unfortunately the log isn’t especially helpful - it’s quite short -:

This does show some communication, but it’s too short to know what’s happening. It’s a little strange that the last two messages are the same, but that’s not uncommon - the question is if it’s stuck in this loop or if it continues. If this is the only think in the log for this device, then I’m afraid I’m not sure what is happening as fundamentally this short log looks ok.

RayBe · March 16, 2017, 7:44am

Chris,
Maybe i should try to add it manually to the database and see what happens.
What do you think?

br,
Raymond

chris · March 16, 2017, 7:12pm

That won’t help - it still won’t create an XML. The lack of an XML indicates that there’s a problem with initialising the device, so the lack of XML itself isn’t the issue.

RayBe · March 16, 2017, 9:18pm

Ah ok I see, what is the best approach to tackle this problem?

chris · March 16, 2017, 9:36pm

Best is to get a log so we can work out what’s wrong with the initialisation.

RayBe · March 16, 2017, 10:48pm

I assume you mean a DEBUG log?
Do you want that filtered in any way? If yes how can I do that?
Thanks

chris · March 16, 2017, 10:50pm

Yep - it’s the only type I can deal with

Nope - rough and ready - just as it comes is fine. The log viewer can filter it - just lo long as it’s no bigger than around 10MB it’s fine.

Thanks.

RayBe · March 23, 2017, 3:25pm

@Chris i finally got some spare time
i completely removed the binding and all the xml-files and started from scratch.
I also added node 2 (the one for which no xml-file is created) as a thing.
All of this is this log:
http://paste.ubuntu.com/24235426/

Thanks for helping,
br,
Raymond

RayBe · March 24, 2017, 11:14am

@chris
I little update, i was reading in the log i pasted and saw that SUC wasn’t enabled.
I am not sure, but i think its best to have it enabled, maybe you can shed a light on this ?
So i enabled SUC, removed node 2 as item and include node 2 as a item, sadly still no xml-file.

Also, i don’t know if i mentioned it but node 2 is used as a inclusion controller.

Thanks,
br,
Raymond

RayBe · March 24, 2017, 11:35am

@chris, a little update, i just found out that there are no XML-files created for any of my battery-operated devices. Maybe this points in a direction.

br,
Raymond

chris · March 24, 2017, 11:51am

I don’t think that SUC will make much difference if your primary controller is already a static controller. IF your primary controller is dynamic, then you should have an SUC in the network.

You need to ensure that devices are properly configured. Battery devices must be woken up, while in direct range of the controller, to allow the system to initialise them.

RayBe · March 24, 2017, 12:02pm

I don’t think that SUC will make much difference if your primary controller is already a static controller. IF your primary controller is dynamic, then you should have an SUC in the network.

How can i check IF my primary controller is dynamic or static?
And is my primary controller my Aeon Labs Stick or my inclusion remote (Remotec Z-URC 550EU) ?
So best practice is to just enable SUC in the binding config?

You need to ensure that devices are properly configured. Battery devices must be woken up, while in direct range of the controller, to allow the system to initialise them.

I did woke them up before i let the binding discover them and i did woke them up before i added them as a thing

chris · March 24, 2017, 12:50pm

Ummm - if you don’t see it moving, then it’s static . If you pick it up and move it from room to room, then it’s not. Basically if it plugs into your PC, then it’s static - if it’s a remote control type device, then it’s not static…

The primary controller will be the first controller used to establish the network. If I remember correctly this is logged in the log file if it’s primary or secondary.

Probably - if you have a remote control type controller, then yes, I would enable SUC - it probably does no harm in any network - if your primary controller is already static it probably won’t help things that’s all…

Yes, but ‘immediately’ AFTER inclusion they need to be woken up a few times to allow the binding to configure the device. If you move the device to another room before this happens, it will likely not work any more. If none of your battery devices work, then I’d hazard a guess that this isn’t being done (of course it might also just be that all your devices are unsupported ;)).

RayBe · March 24, 2017, 3:47pm

My other battery devices do work and are being recognized properly (aeon labs door/window sensor and a hsm100). But there are just no xml file being created for them.
I will try to do a few wake-ups, is there anything else I can do? Or is there a specific order in which I must wake them, let the binding find them and add the devices as things?

Btw is the log I pasted, the correct one?

Br,
Raymond

chris · March 24, 2017, 4:09pm

This means they have not initialised fully. They may work - that’s at least parly independant of the initialisation sequence.

Not really - the adding of things is completely separated from the logic at the protocol level in the binding.

I’ve not had the chance to look at it yet…

Cheers
Chris