My struggle with Zwave.. HEEEEELP

dries_dokter · September 14, 2016, 9:21pm

As I did not get any reaction to my previous post, I deciced to start from scratch.
So I excluded all zwave devices. Then started with just one WALLC-S Wall Controller (a battery powered device)…

That’s where my struggle started, I included the WALLC-S , it was added to the z-wave network as node3.
In OpenHab2 a thing was added Node3, “unknown device”. I woke up node 3 a couple of times manually (and saw in the zwave log that it was sending an information frame) but OpenHab kept saying Node3 " unknown device.
At a certain point the zwave log showed that the device was actually recognised but still Node3: unknown device…
And as long as a device is unrecognised I have no idea how to create items for that device (see previous post)…
I also cannot set the associations and change button press behaviour to selecting a scene.

After 2 days of unknown device I decided to remove Thing Node3… Openhab then reported a new thing:
Node 3: WALLC-S Wall Controller…

So after that correct configuration items show up, so I tried to set the associations and change other parameters… And that is where I am stuck… for more than a week now. I can wake-up the device by hand as often as I want, parameters are not getting across.And because of that, I can’t switch to using scenes and I can’t associate any groups to Node1…
So the controller does not see any commands from this switch…

What can I do to get past this point ??

In the zwave.log the wake-up always seems to end in ABORT:

2016-09-14 22:55:07.874 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete
2016-09-14 23:18:03.375 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 18 01 5E 70 85 2D 8E 80 84 8F 5A 59 5B 73 86 72 EF 20 5B 26 27 2B 60 A8
2016-09-14 23:18:03.379 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-14 23:18:03.380 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1E 00 49 84 03 18 04 18 01 5E 70 85 2D 8E 80 84 8F 5A 59 5B 73 86 72 EF 20 5B 26 27 2B 60 A8
2016-09-14 23:18:03.380 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1E 00 49 84 03 18 04 18 01 5E 70 85 2D 8E 80 84 8F 5A 59 5B 73 86 72 EF 20 5B 26 27 2B 60 A8
2016-09-14 23:18:03.380 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 03 18 04 18 01 5E
 70 85 2D 8E 80 84 8F 5A 59 5B 73 86 72 EF 20 5B 26 27 2B 60
2016-09-14 23:18:03.381 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received.
2016-09-14 23:18:03.381 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Is awake with 1 messages in the wake-up queue.
2016-09-14 23:18:03.381 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2016-09-14 23:18:03.381 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveWakeUpEvent
2016-09-14 23:18:03.382 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Wakeup during initialisation.
2016-09-14 23:18:03.382 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - DETAILS: queue length(1), free to send(false)
2016-09-14 23:18:03.382 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - queued packet. Queue length is 1
2016-09-14 23:18:03.383 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-09-14 23:18:03.383 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-09-14 23:18:03.383 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-09-14 23:18:03.383 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 03 01 00 25 06 C5
2016-09-14 23:18:03.383 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate
, dest=3, callback=6, payload=03 01 00
2016-09-14 23:18:03.384 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 08 00 13 03 01 00 25 06 C5
2016-09-14 23:18:03.391 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 03 02 84 07 71
2016-09-14 23:18:03.393 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-14 23:18:03.393 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2016-09-14 23:18:03.393 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71
2016-09-14 23:18:03.393 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 03 02 84 07 71
2016-09-14 23:18:03.394 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 02 84
07
2016-09-14 23:18:03.394 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DETAILS)
2016-09-14 23:18:03.394 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Incoming command class WAKE_UP
2016-09-14 23:18:03.394 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Received Wake Up Request
2016-09-14 23:18:03.394 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Received WAKE_UP_NOTIFICATION
2016-09-14 23:18:03.394 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Is awake with 0 messages in the wake-up queue.
2016-09-14 23:18:03.394 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2016-09-14 23:18:03.394 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveWakeUpEvent
2016-09-14 23:18:03.395 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Wakeup during initialisation.
2016-09-14 23:18:03.395 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - DETAILS: queue length(1), free to send(false)
2016-09-14 23:18:03.395 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - queued packet. Queue length is 1
2016-09-14 23:18:03.395 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2016-09-14 23:18:03.396 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=3, callback=7, payload=03 01 00
2016-09-14 23:18:03.414 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 03 02 84 07 71
2016-09-14 23:18:03.417 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-14 23:18:03.417 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 03 02 84 07 71
2016-09-14 23:18:03.417 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 03 02 84 07 71
2016-09-14 23:18:03.418 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 02 84 07
2016-09-14 23:18:03.418 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DETAILS)
2016-09-14 23:18:03.418 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Incoming command class WAKE_UP
2016-09-14 23:18:03.419 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Received Wake Up Request
2016-09-14 23:18:03.419 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Received WAKE_UP_NOTIFICATION
2016-09-14 23:18:03.419 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Is awake with 0 messages in the wake-up queue.
2016-09-14 23:18:03.419 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2016-09-14 23:18:03.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveWakeUpEvent
2016-09-14 23:18:03.420 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Wakeup during initialisation.
2016-09-14 23:18:03.420 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - DETAILS: queue length(1), free to send(false)
2016-09-14 23:18:03.420 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: loop - DETAILS try 2: stageAdvanced(false)
2016-09-14 23:18:03.421 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: received RequestNodeInfo
2016-09-14 23:18:03.421 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to INCLUSION_START
2016-09-14 23:18:03.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-14 23:18:03.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-14 23:18:03.422 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: loop - INCLUSION_START try 0: stageAdvanced(true)
2016-09-14 23:18:03.422 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: Unknown node state INCLUSION_START encountered.
2016-09-14 23:18:03.422 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to IDENTIFY_NODE
2016-09-14 23:18:03.422 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-14 23:18:03.423 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-14 23:18:03.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: loop - IDENTIFY_NODE try 0: stageAdvanced(true)
2016-09-14 23:18:03.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: PROTOINFO - send IdentifyNode
2016-09-14 23:18:03.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - queued packet. Queue length is 1
2016-09-14 23:18:03.424 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2016-09-14 23:18:03.424 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=3, callback=7, payload=03 01 00
2016-09-14 23:18:03.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 80 03 40 31
2016-09-14 23:18:03.481 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-14 23:18:03.482 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 03 03 80 03 40 31
2016-09-14 23:18:03.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 03 03 80 03 40 31
2016-09-14 23:18:03.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 03 80 03 40
2016-09-14 23:18:03.483 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:IDENTIFY_NODE)
2016-09-14 23:18:03.483 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 3: Incoming command class BATTERY
2016-09-14 23:18:03.483 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 3: Received Battery Request
2016-09-14 23:18:03.483 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 3: Battery report value = 64
2016-09-14 23:18:03.484 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2016-09-14 23:18:03.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2016-09-14 23:18:03.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = BATTERY, value = 64
2016-09-14 23:18:03.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:42ea3240:node3:battery-level to 64 [DecimalType]
2016-09-14 23:18:03.485 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Message has Ack Pending: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=3, callback=7, payload=03 01 00
2016-09-14 23:18:04.424 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: No more messages, go back to sleep
2016-09-14 23:18:04.425 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2016-09-14 23:18:04.425 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2016-09-14 23:18:08.391 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2016-09-14 23:18:08.391 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Sending ABORT Message = 01 03 00 16 EA
2016-09-14 23:18:08.391 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2016-09-14 23:18:08.392 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2016-09-14 23:18:08.836 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 3: Timeout while sending message. Requeueing - 0 attempts left!
2016-09-14 23:18:08.837 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Is sleeping
2016-09-14 23:18:08.837 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.
2016-09-14 23:18:08.837 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2016-09-14 23:18:08.837 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Message already on the wake-up queue. Removing original.
2016-09-14 23:18:08.837 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.
2016-09-14 23:18:08.838 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2016-09-14 23:18:08.838 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 03 B9
2016-09-14 23:18:08.838 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 03 B9
2016-09-14 23:18:08.855 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 18 01 65
2016-09-14 23:18:08.857 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-14 23:18:08.857 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 53 9C 01 04 18 01 65
2016-09-14 23:18:08.858 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 53 9C 01 04 18 01 65
2016-09-14 23:18:08.858 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=53 9C 01 04 18 01
2016-09-14 23:18:08.859 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: ProtocolInfo
2016-09-14 23:18:08.859 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Listening = false
2016-09-14 23:18:08.859 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Routing = true
2016-09-14 23:18:08.859 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Beaming = true
2016-09-14 23:18:08.859 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Version = 4
2016-09-14 23:18:08.860 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: FLIRS = false
2016-09-14 23:18:08.860 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Security = false
2016-09-14 23:18:08.860 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Max Baud = 40000
2016-09-14 23:18:08.860 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Basic = Routing Slave
2016-09-14 23:18:08.860 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Generic = Remote Switch 2
2016-09-14 23:18:08.860 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Specific = Multilevel Remote Switch
2016-09-14 23:18:08.861 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class NO_OPERATION
2016-09-14 23:18:08.861 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class NO_OPERATION, endpoint null created
2016-09-14 23:18:08.861 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Version = 1, version set. Enabling extra functionality.
2016-09-14 23:18:08.861 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class BASIC
2016-09-14 23:18:08.861 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class BASIC, endpoint null created
2016-09-14 23:18:08.862 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, callback=0, payload=03
2016-09-14 23:18:08.862 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=53 9C 01 04 18 01
2016-09-14 23:18:08.862 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!
2016-09-14 23:18:08.862 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-14 23:18:08.862 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - IDENTIFY_NODE: Transaction complete (IdentifyNode:Request) success(true)
2016-09-14 23:18:08.863 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - checking initialisation queue. Queue size 1.
2016-09-14 23:18:08.863 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - message removed from queue. Queue size 0.
2016-09-14 23:18:08.863 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - IDENTIFY_NODE: queue length(0), free to send(true)
2016-09-14 23:18:08.863 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: loop - IDENTIFY_NODE try 1: stageAdvanced(false)
2016-09-14 23:18:08.863 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to MANUFACTURER
2016-09-14 23:18:08.863 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-14 23:18:08.864 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-14 23:18:08.864 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true)
2016-09-14 23:18:08.864 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: MANUFACTURER - send ManufacturerSpecific
2016-09-14 23:18:08.865 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 3: Creating new message for command MANUFACTURER_SPECIFIC_GET
2016-09-14 23:18:08.865 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - queued packet. Queue length is 1
2016-09-14 23:18:08.865 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.
2016-09-14 23:18:08.865 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.
2016-09-14 23:18:08.866 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 25ms/131ms.
2016-09-14 23:18:08.866 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2016-09-14 23:18:08.866 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Message already on the wake-up queue. Removing original.
2016-09-14 23:18:08.866 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.
2016-09-14 23:18:08.867 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-09-14 23:18:08.867 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 3: Putting message SendData in wakeup queue.

jaydee73 · September 15, 2016, 6:34am

According to the database from chris (www.cd-jackson.com, in case you don’t knew this yet) the device has a parameter 25 where a wakeup block can be enabled/disabled. Interestingly the default is “wakeup blocked”. But the manual says that one can always wake up the device by pressing button 2. Don’t know if this is related to your problem.

Other than that I can only suggest to make a factory reset of the device and try again.

What kind of controller do you use? I’ve seen that the device supports secure communication. As this is not fully supported by the binding at the moment, you should not use this feature at all while including the device.

And you should check if there is a XML file created for your node. Sometimes it helps to delete this file and let the binding discover the device again (no re-include!).

Do you have made the inclusion with the device near the controller? They shouldn’t be to far apart. I like my AEON G5 USB stick with integrated battery, so I can include the devices which are mounted at their final places and take the stick to the device.

I assume the other zwave device do work properly? Just to make sure the binding/controller/general configuration is working.

Regarding manual wake up: I am using a sensative strip (door sensor), which has to be woken up about a dozen times to get fully initialized. Battery operated devices are strange sometimes…

dries_dokter · September 15, 2016, 7:05am

Thank you! Will look into all this once I am back home.

My controller is a ZME UZB1
I am indeed waking up the device by pressing button 2 in management mode.
(basically that is what I did at the start of the log file above). That wake-up should
make it take the update for parameter 25 But somehow that is not happening (chicken/egg?)
Your remark on secure communication sounds like the best lead for improvement, will start from scratch tonight and make sure it is not using secure communication
I only have 5 zwave WALLC-S switches for use with openHAB. At this moment there is only one (wanted to not complicate things) included. But it all worked just fine in openhab 1.8

Indeed getting these battery operated devices to work is a big hassle. But waking them up, waiting a couple of days for it to wake-up by itself, apply some vodooo , etc used to do the trick. But not this time…

dan12345 · September 15, 2016, 9:54am

I find all zwave battery operated devices, and the WALLC-S in particular, to be difficult/flaky to setup. Sometimes I have odd behaviour which resolves itself if I exclude/include. I have had to return several WALLC-S units because they just wouldn’t include properly, and had the kind of problems you describe. The replacement units worked fine (eventually).

By contrast mains-powered zwave devices have always been completely reliable for me.

dries_dokter · September 15, 2016, 7:20pm

Starting over and switching of the secure inclusion did not help much. Again “unknow device” shows up, waking it up manually does not help, removing the Thing etc. stuck at the very same spot…

So then I thought why not give 1.8.3 and Habmin1 a try… It worked within 5 minutes…:

Opened the zwave binding in habmin 2
Manually woke-up the WALLC-S: it appears as a WALLC-S, with all configuration parameters
I changed the device configuration, the items are shown in yellow in HABmin,
Manually woke-up the WALLC-S, items turn white (as in: configuration updated
Changed Node 1 to " member" for all association groups “0 of 10 members”
Manually woke-up WALLC-S: association is accepted “1 of 10 members”

I did the exact same thing, works in 1.8 but not in 2b4… So there must be a setting or something that I am missing…
I have logs for both 1.8 and 2.0B4 scenarios

Starting openhab2 I am back to where I started as described in this thread:

chris · September 15, 2016, 7:51pm

Please provide the OH2 debug log and I’ll take a look.

dries_dokter · September 15, 2016, 8:00pm

https://1drv.ms/u/s!AqPufRD6FolTgf8JXG3Z-ipydM9CUw

Thank you Chris!

chris · September 15, 2016, 9:31pm

I’m a bit surprised it’s not being discovered - according to the log, it is discovered (incorrectly it seems) as the zwave.me keyfob since there is overlapping IDs in the database which we’ll need to sort out!


2016-09-15 20:53:26.539 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Checking zwave:zwaveme_kfob_00_000
2016-09-15 20:53:26.540 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device already known - properties will be updated.
2016-09-15 20:53:26.541 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery resolved to thingType zwave:zwaveme_kfob_00_000

So, if for a minute we ignore the fact that it’s found the incorrect device type, it shouldn’t say it’s unknown. Have you added the device as a thing, or is it still sitting in the inbox? If it’s added as a thing, what do you see if you look in HABmin in the attributes section for this device?

Hmmm - I also see this in the log -:

2016-09-15 20:53:43.665 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising Thing Node...
2016-09-15 20:53:43.665 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Controller status changed to ONLINE.
2016-09-15 20:53:43.665 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Controller is ONLINE. Starting device initialisation.
2016-09-15 20:53:43.665 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising channel zwave:device:42ea3240:node4:scene_number
2016-09-15 20:53:43.669 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:42ea3240:node4:scene_number --> REFRESH
2016-09-15 20:53:43.669 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-09-15 20:53:43.669 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:42ea3240:node4:battery-level --> REFRESH
2016-09-15 20:53:43.669 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-09-15 20:53:43.682 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising cmd channel zwave:device:42ea3240:node4:scene_number
2016-09-15 20:53:43.682 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising poll channel zwave:device:42ea3240:node4:scene_number
2016-09-15 20:53:43.682 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising state channel zwave:device:42ea3240:node4:scene_number
2016-09-15 20:53:43.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising state channel zwave:device:42ea3240:node4:scene_number
2016-09-15 20:53:43.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising channel zwave:device:42ea3240:node4:battery-level
2016-09-15 20:53:43.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising cmd channel zwave:device:42ea3240:node4:battery-level
2016-09-15 20:53:43.684 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising poll channel zwave:device:42ea3240:node4:battery-level
2016-09-15 20:53:43.684 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising state channel zwave:device:42ea3240:node4:battery-level

This seems to indicate that the channels are all initialised, so it looks like the device is fully discovered, so now I’m really confused if you say it’s showing as unknown. Can you provide a screenshot or two to show me what you’re seeing?

dries_dokter · September 15, 2016, 9:42pm

Hmm, that does sound familiar, at some point, I did see that pass by at some point…
What I will do is:

exclude the device,
do a factory reset on the device…
stop openHAB2
remove zwave.log
start openHAB2
Include the WALLC-S, etc.
So I have a clear log showing it all…

Current sceenshots:
I removed the Thing , triggered a discovery and then it appears like this:
https://1drv.ms/i/s!AqPufRD6FolTgf8Kp9X0P2v4dwxJag
This is the list of things:
https://1drv.ms/i/s!AqPufRD6FolTgf8L-Tt-Uq-bBIT94Q

Will try and create the log I just mentioned

igorrobertifoc · September 15, 2016, 9:47pm

Yes, was my same problem.I removed from things on Paper UI,I waited 1 day and relaunched the discovery…
After this was discovered correctly. Maybe is initialised good on 2PM (wake up automatically)

chris · September 15, 2016, 9:52pm

From this list, if you click on node 4, then on the right side of the screen you should have the option to view attributes - what does that show?

A log of this would be good - just to make sure it’s working the same as the previous log since that all looked ok…

dries_dokter · September 15, 2016, 10:05pm

As I already started creating that log I can no longer look at node 4 ooops. But from memory manufacturer etc. would show up empty and routing_slave, remote switch and then some… The last wake-up time would actually refelct the last time I manually woke it up…

Here’s the clean log:
Started openhab with just the zwave controller…
From that point:

Started zwave discovery

Pressed button 1 on WALLC-S for inclusion

New thing in Inbox: Note 5

Added as Thing: Node 5 , unknown device

Manually woke-up WALLC-S (management mode, button 2) (nothing happens)

Started Zwave discovery again

removed thing Node 5

Started discovery again
Now Note 5 shows up as: KFOB 4 button keyfob but parameters look similar to what WALLC-S has so just changed some of them see screen shot
Parameters are pending but waking up the device will not make them current… (stay pending)…

Log ends there…

chris · September 15, 2016, 10:23pm

Ok, but in your new log, it’s node 5, so can’t you look at this? The new log also looks like discovery is working ok -:

2016-09-15 23:50:16.986 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Checking zwave:zwaveme_kfob_00_000
2016-09-15 23:50:16.987 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery resolved to thingType zwave:zwaveme_kfob_00_000
2016-09-15 23:50:17.081 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 1
2016-09-15 23:50:17.081 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.
2016-09-15 23:50:17.081 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-09-15 23:50:17.083 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-09-15 23:50:17.083 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 01 30 
2016-09-15 23:50:17.083 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 01 30 
2016-09-15 23:50:17.427 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 01 00 00 B2 
2016-09-15 23:50:17.430 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-15 23:50:17.430 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 01 00 00 B2 
2016-09-15 23:50:17.430 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 01 00 00 B2 
2016-09-15 23:50:17.430 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00 
2016-09-15 23:50:17.430 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2016-09-15 23:50:17.430 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-09-15 23:50:17.431 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=81 01 
2016-09-15 23:50:17.431 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00 
2016-09-15 23:50:17.431 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-09-15 23:50:17.431 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-15 23:50:17.431 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 22ms/362ms.
2016-09-15 23:50:25.705 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:device, thing.id=zwave:device:42ea3240:node5, service.id=338, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-09-15 23:50:25.706 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-09-15 23:50:25.706 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=339, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-09-15 23:50:25.717 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller status changed to ONLINE.
2016-09-15 23:50:25.717 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller initialised.
2016-09-15 23:50:25.717 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller is ONLINE. Starting device initialisation.
2016-09-15 23:50:25.717 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller status changed to ONLINE.
2016-09-15 23:50:25.717 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller is ONLINE. Starting device initialisation.
2016-09-15 23:50:25.925 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-09-15 23:50:25.927 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller initialised.
2016-09-15 23:50:25.927 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller status changed to ONLINE.
2016-09-15 23:50:25.927 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller is ONLINE. Starting device initialisation.
2016-09-15 23:50:25.928 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller status changed to ONLINE.
2016-09-15 23:50:25.928 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Controller is ONLINE. Starting device initialisation.
2016-09-15 23:50:25.929 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating node properties. Controller not found.
2016-09-15 23:50:25.929 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising Thing Node...
2016-09-15 23:50:25.929 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising channel zwave:device:42ea3240:node5:scene_number
2016-09-15 23:50:25.932 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:42ea3240:node5:scene_number --> REFRESH
2016-09-15 23:50:25.932 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-09-15 23:50:25.932 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:42ea3240:node5:battery-level --> REFRESH
2016-09-15 23:50:25.932 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-09-15 23:50:25.947 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising cmd channel zwave:device:42ea3240:node5:scene_number
2016-09-15 23:50:25.947 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising poll channel zwave:device:42ea3240:node5:scene_number
2016-09-15 23:50:25.947 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising state channel zwave:device:42ea3240:node5:scene_number
2016-09-15 23:50:25.947 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising state channel zwave:device:42ea3240:node5:scene_number
2016-09-15 23:50:25.948 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising channel zwave:device:42ea3240:node5:battery-level
2016-09-15 23:50:25.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising cmd channel zwave:device:42ea3240:node5:battery-level
2016-09-15 23:50:25.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising poll channel zwave:device:42ea3240:node5:battery-level
2016-09-15 23:50:25.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising state channel zwave:device:42ea3240:node5:battery-level
2016-09-15 23:50:25.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling intialised at 1800 seconds - start in 1800000 milliseconds.

I’ve found a small bug which could be the reason for this, although I’m not certain since the binding seems to be creating channels… Anyway, please try this again tomorrow with the next nightly snapshot and let me know if it works… If not, then please provide an updated log an image of the attributes…

dries_dokter · September 15, 2016, 10:29pm

Here’s the attributes:
https://1drv.ms/i/s!AqPufRD6FolTgf8Py66zfPYTR_UsVg

Will check the new snapshot tomorrow , thanks for looking into this!
And thanks for all your work on zwave, gladly made use of it the past years

chris · September 15, 2016, 10:31pm

Hmmm - from the image, I don’t think the update will help, but let’s see. The image also seems to indicate that everything is ok so it’s quite confusing

chris · September 15, 2016, 10:42pm

If you get a chance, can you provide a screenshot of the channels and the overview section of the node 5 thing (ie the part above the attributes).

dries_dokter · September 16, 2016, 5:24am

Screenshots are Here

chris · September 16, 2016, 6:49am

So, everything looks like it’s working fine to me. The device is detected ok, you have the configuration parameters showing up and channels are linked…

Are there still any problems?

dries_dokter · September 16, 2016, 9:08am

Well small thing: this is a WALLC-S not a KFOB but that’s cosmetic.
But the real issue: It is not taking any of the parameters that I set , I have woken-up the the node manually and with a wake-up time of a day it is bound to wake-up by itself too, but parameters stay pending… That’s where I left it yesterday evening, some parameters showed Pending. I Quickly took the screenshots this morning… and it appears the parameters no longer have the pending label, but have not changed either.

In openHAB1.8 I would set the parameters (change action on group x to Scenes), wake up the device manually once and parameters are taken.

I am doing my best to stay within reproducible scenarios (keeping track of what I have done/ changed/ deleted.) In that way I can tell the story that comes with the log file… Will try and do that for the parameter change too: change them, take screenshot, wake-up device etc etc…

I have four of these switches, might also try to add one of the 3…

chris · September 16, 2016, 9:34am

Yes - that’s what I said yesterday. The database needs to be updated, but your problem was that the device wasn’t detected so I thought this is a secondary problem at the moment?

Ok, so this is now a different issue that it not being detected? Please provide a log showing this issue - I don’t think there’s a systematic problem with configuration, and in order to establish what is happening I really need to see a log - sorry.