Zwave device pairing not working anymore

[Alan_Alberghini]

Hello @chris,

using the latest snapshot of the binding (version 2.0.0.201610091257), I discovered that I’m unable to complete any device inclusion operation. This was not the case with the 2.0.0.201610061822 snapshot and earlier.
Using a Fibaro FGK-10x as test device, which normally requires 2 triple tamper button presses to complete device inclusion and propert detection, is this:
First tamper button triple press

2016-10-11 13:20:38.785 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2016-10-11 13:20:38.816 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-10-11 13:20:38.862 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01 
2016-10-11 13:20:38.879 [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-10-11 13:20:38.890 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-10-11 13:20:38.896 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:38.902 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 263ms/2704ms.
2016-10-11 13:20:41.685 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 02 00 00 B1 
2016-10-11 13:20:41.735 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:20:41.745 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 02 00 00 B1 
2016-10-11 13:20:41.750 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 02 00 00 B1 
2016-10-11 13:20:41.767 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 02 00 00 
2016-10-11 13:20:41.771 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2016-10-11 13:20:41.788 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01 
2016-10-11 13:20:41.802 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 02 00 00 
2016-10-11 13:20:41.819 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-10-11 13:20:41.823 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:41.850 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 16 00 4A 01 03 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B C1 
2016-10-11 13:20:41.875 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:20:41.884 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 16 00 4A 01 03 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B C1 
2016-10-11 13:20:41.909 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 16 00 4A 01 03 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B C1 
2016-10-11 13:20:41.921 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 03 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 
2016-10-11 13:20:41.925 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 11: Adding slave.
2016-10-11 13:20:41.931 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-10-11 13:20:41.936 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2016-10-11 13:20:41.941 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-10-11 13:20:41.952 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 01 B4 
2016-10-11 13:20:41.954 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
2016-10-11 13:20:41.963 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 01 B4 
2016-10-11 13:20:41.966 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end inclusion
2016-10-11 13:20:41.973 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Including node.
2016-10-11 13:20:41.983 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class SENSOR_BINARY
2016-10-11 13:20:42.005 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class SENSOR_BINARY, endpoint null created
2016-10-11 13:20:42.010 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class SENSOR_BINARY.
2016-10-11 13:20:42.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class SENSOR_BINARY to the list of supported command classes.
2016-10-11 13:20:42.019 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class SENSOR_ALARM
2016-10-11 13:20:42.025 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class SENSOR_ALARM, endpoint null created
2016-10-11 13:20:42.031 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class SENSOR_ALARM.
2016-10-11 13:20:42.037 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class SENSOR_ALARM to the list of supported command classes.
2016-10-11 13:20:42.042 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class ASSOCIATION
2016-10-11 13:20:42.048 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class ASSOCIATION, endpoint null created
2016-10-11 13:20:42.066 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class ASSOCIATION.
2016-10-11 13:20:42.070 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class ASSOCIATION to the list of supported command classes.
2016-10-11 13:20:42.093 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-11 13:20:42.099 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class MANUFACTURER_SPECIFIC, endpoint null created
2016-10-11 13:20:42.103 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class MANUFACTURER_SPECIFIC.
2016-10-11 13:20:42.129 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes.
2016-10-11 13:20:42.133 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class CONFIGURATION
2016-10-11 13:20:42.149 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class CONFIGURATION, endpoint null created
2016-10-11 13:20:42.154 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class CONFIGURATION.
2016-10-11 13:20:42.181 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class CONFIGURATION to the list of supported command classes.
2016-10-11 13:20:42.196 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class VERSION
2016-10-11 13:20:42.201 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class VERSION, endpoint null created
2016-10-11 13:20:42.216 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class VERSION.
2016-10-11 13:20:42.220 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class VERSION to the list of supported command classes.
2016-10-11 13:20:42.234 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class BATTERY
2016-10-11 13:20:42.239 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class BATTERY, endpoint null created
2016-10-11 13:20:42.244 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class BATTERY.
2016-10-11 13:20:42.258 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class BATTERY to the list of supported command classes.
2016-10-11 13:20:42.263 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class CRC_16_ENCAP
2016-10-11 13:20:42.288 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 05 0B 00 BD 
2016-10-11 13:20:42.290 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class CRC_16_ENCAP, endpoint null created
2016-10-11 13:20:42.299 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class CRC_16_ENCAP.
2016-10-11 13:20:42.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class CRC_16_ENCAP to the list of supported command classes.
2016-10-11 13:20:42.318 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class WAKE_UP
2016-10-11 13:20:42.339 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 0B 00 BE 
2016-10-11 13:20:42.345 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class WAKE_UP, endpoint null created
2016-10-11 13:20:42.356 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class WAKE_UP.
2016-10-11 13:20:42.361 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class WAKE_UP to the list of supported command classes.
2016-10-11 13:20:42.376 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class FIRMWARE_UPDATE_MD
2016-10-11 13:20:42.381 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class FIRMWARE_UPDATE_MD, endpoint null created
2016-10-11 13:20:42.396 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Inclusion is adding command class FIRMWARE_UPDATE_MD.
2016-10-11 13:20:42.400 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class FIRMWARE_UPDATE_MD to the list of supported command classes.
2016-10-11 13:20:42.444 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01 
2016-10-11 13:20:42.469 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 03 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 
2016-10-11 13:20:42.473 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-10-11 13:20:42.489 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:42.505 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 527ms/2704ms.
2016-10-11 13:20:42.522 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
2016-10-11 13:20:42.528 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 05 0B 00 BD 
2016-10-11 13:20:42.551 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 05 0B 00 BD 
2016-10-11 13:20:42.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 05 0B 00 
2016-10-11 13:20:42.562 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Protocol done.
2016-10-11 13:20:42.578 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
2016-10-11 13:20:42.584 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 05 0B 00 
2016-10-11 13:20:42.608 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-10-11 13:20:42.613 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:42.625 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:20:42.631 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 06 0B 00 BE 
2016-10-11 13:20:42.639 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 06 0B 00 BE 
2016-10-11 13:20:42.645 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 0B 00 
2016-10-11 13:20:42.649 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2016-10-11 13:20:42.653 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-10-11 13:20:42.660 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovered
2016-10-11 13:20:43.668 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Starting initialisation from INCLUSION_START
2016-10-11 13:20:43.673 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - INCLUSION_START: queue length(0), free to send(true)
2016-10-11 13:20:43.680 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - INCLUSION_START try 1: stageAdvanced(false)
2016-10-11 13:20:43.686 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: Unknown node state INCLUSION_START encountered.
2016-10-11 13:20:43.693 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - advancing to IDENTIFY_NODE
2016-10-11 13:20:43.699 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-10-11 13:20:43.704 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - IDENTIFY_NODE try 0: stageAdvanced(true)
2016-10-11 13:20:43.709 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: PROTOINFO - send IdentifyNode
2016-10-11 13:20:43.716 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - queued packet. Queue length is 1
2016-10-11 13:20:43.722 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-10-11 13:20:43.722 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-10-11 13:20:43.731 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 0B B1 
2016-10-11 13:20:43.732 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
2016-10-11 13:20:43.738 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 0B B1 
2016-10-11 13:20:43.741 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 0B 00 
2016-10-11 13:20:43.748 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-10-11 13:20:43.753 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:43.758 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - IDENTIFY_NODE: Transaction complete (IdentifyNode:Request) success(true)
2016-10-11 13:20:43.759 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 00 04 20 01 5C 
2016-10-11 13:20:43.766 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - checking initialisation queue. Queue size 1.
2016-10-11 13:20:43.772 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - message removed from queue. Queue size 0.
2016-10-11 13:20:43.777 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - IDENTIFY_NODE: queue length(0), free to send(true)
2016-10-11 13:20:43.784 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - IDENTIFY_NODE try 1: stageAdvanced(false)
2016-10-11 13:20:43.789 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - advancing to MANUFACTURER
2016-10-11 13:20:43.798 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-10-11 13:20:43.804 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true)
2016-10-11 13:20:43.809 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: MANUFACTURER - send ManufacturerSpecific
2016-10-11 13:20:43.816 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 11: Creating new message for command MANUFACTURER_SPECIFIC_GET
2016-10-11 13:20:43.822 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - queued packet. Queue length is 1
2016-10-11 13:20:43.829 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 11: Putting message SendData in wakeup queue.
2016-10-11 13:20:43.835 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 93ms/2704ms.
2016-10-11 13:20:43.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:20:43.847 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 53 9C 00 04 20 01 5C 
2016-10-11 13:20:43.853 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 53 9C 00 04 20 01 5C 
2016-10-11 13:20:43.859 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=53 9C 00 04 20 01 
2016-10-11 13:20:43.864 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: ProtocolInfo
2016-10-11 13:20:43.869 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Listening = false
2016-10-11 13:20:43.890 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Routing = true
2016-10-11 13:20:43.894 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Beaming = true
2016-10-11 13:20:43.899 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Version = 4
2016-10-11 13:20:43.905 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: FLIRS = false
2016-10-11 13:20:43.909 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Security = false
2016-10-11 13:20:43.927 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Max Baud = 40000
2016-10-11 13:20:43.935 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Basic = Routing Slave
2016-10-11 13:20:43.941 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Generic = Binary Sensor
2016-10-11 13:20:43.946 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 11: Specific = Routing Binary Sensor
2016-10-11 13:20:43.952 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class NO_OPERATION
2016-10-11 13:20:43.957 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class NO_OPERATION, endpoint null created
2016-10-11 13:20:43.962 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Version = 1, version set. Enabling extra functionality.
2016-10-11 13:20:43.970 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class NO_OPERATION to the list of supported command classes.
2016-10-11 13:20:43.976 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class BASIC
2016-10-11 13:20:43.981 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class BASIC, endpoint null created
2016-10-11 13:20:43.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Adding command class BASIC to the list of supported command classes.
2016-10-11 13:20:43.993 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Creating new instance of command class SENSOR_BINARY
2016-10-11 13:20:43.998 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 11: Command class SENSOR_BINARY, endpoint null created
2016-10-11 13:20:44.004 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, callback=0, payload=0B 
2016-10-11 13:20:44.010 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=53 9C 00 04 20 01 
2016-10-11 13:20:44.016 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false        transaction complete!
2016-10-11 13:20:44.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:44.027 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 11: Putting message SendData in wakeup queue.
2016-10-11 13:20:44.032 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - MANUFACTURER: Transaction complete (IdentifyNode:Request) success(true)
2016-10-11 13:20:44.037 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - checking initialisation queue. Queue size 1.
2016-10-11 13:20:55.181 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
2016-10-11 13:20:55.195 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2016-10-11 13:20:55.201 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-10-11 13:20:55.201 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-10-11 13:20:55.206 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end inclusion
2016-10-11 13:20:55.210 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 01 B4 
2016-10-11 13:20:55.216 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 01 B4 
2016-10-11 13:20:55.275 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 0B 00 BE 
2016-10-11 13:20:55.285 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:20:55.293 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 06 0B 00 BE 
2016-10-11 13:20:55.298 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 06 0B 00 BE 
2016-10-11 13:20:55.303 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 0B 00 
2016-10-11 13:20:55.308 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2016-10-11 13:20:55.313 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-10-11 13:20:55.320 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device already known.
2016-10-11 13:20:55.324 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Newly included node already initialising at MANUFACTURER
2016-10-11 13:20:55.327 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
2016-10-11 13:20:55.330 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 0B 00 
2016-10-11 13:20:55.332 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2016-10-11 13:20:55.335 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-11 13:20:55.337 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 118ms/2704ms.

Second tamper button triple press

2016-10-11 13:21:03.681 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 15 00 49 84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 47 
2016-10-11 13:21:03.696 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:21:03.699 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 15 00 49 84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 47 
2016-10-11 13:21:03.702 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 15 00 49 84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 47 
2016-10-11 13:21:03.706 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 
2016-10-11 13:21:03.715 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 11: Application update request. Node information received.
2016-10-11 13:21:03.718 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Node is ALIVE. Init stage is MANUFACTURER.
2016-10-11 13:21:03.721 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2016-10-11 13:21:03.723 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node Status event during initialisation - Node is ALIVE
2016-10-11 13:21:03.726 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - MANUFACTURER: queue length(1), free to send(false)
2016-10-11 13:21:03.728 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - queued packet. Queue length is 1
2016-10-11 13:21:03.730 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 11: Message already on the wake-up queue. Removing original.
2016-10-11 13:21:03.735 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 11: Putting message SendData in wakeup queue.
2016-10-11 13:21:03.737 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 11: Node Status event - Node is ALIVE
2016-10-11 13:21:03.741 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
2016-10-11 13:21:03.745 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 
2016-10-11 13:21:03.747 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=0, expected=AddNodeToNetwork, cancelled=false      MISMATCH

Third tamper button triple press

2016-10-11 13:21:07.977 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 15 00 49 84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 47 
2016-10-11 13:21:07.984 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-11 13:21:07.988 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 15 00 49 84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 47 
2016-10-11 13:21:07.992 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 15 00 49 84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 47 
2016-10-11 13:21:07.996 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 
2016-10-11 13:21:07.999 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 11: Application update request. Node information received.
2016-10-11 13:21:08.002 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
2016-10-11 13:21:08.006 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 0B 0F 04 20 01 30 9C 85 72 70 86 80 56 84 7A EF 2B 
2016-10-11 13:21:08.008 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=0, expected=AddNodeToNetwork, cancelled=false      MISMATCH

and so on (the same log lines repeat with every triple button press)
From what I can understand from the log, now the binding gives a MISMATCH because it was waiting for an AddNodeToNetwork message or ACK, while the device sent an ApplicationUpdate message.
Could this be related to the recent PR 166, where NIFs are not used anymore as wakeup notifications?

[chris (Chris Jackson)]

I don’t really see anything wrong, and I don’t think anything has changed with inclusion. The node seems to add just fine - it’s the wakeup that doesn’t work.

@Alan_Alberghini

From what I can understand from the log, now the binding gives a MISMATCH because it was waiting for an AddNodeToNetwork message or ACK, while the device sent an ApplicationUpdate message.

I don’t think this is an issue - this is normal.

@Alan_Alberghini

Could this be related to the recent PR 166, where NIFs are not used anymore as wakeup notifications

Yes - quite possibly. I’ve just reverted this change and I’ll have to look at another way to solve the NIF problem .

[ChrisSFoot (Chris Foot)]

I seem to be suffering the same issue with my Fibaro fgms-001, running the latest snapshot as of now (2.0.0.201610131900). It includes ok but never gets the full information from the device, regardless of how many times I wake it.

[mhilbush (Mark)]

@ChrisSFoot

suffering the same issue with my Fibaro fgms-001

The button triple-press generates a NIF, not a WAKE_UP. Try the latest build which reverts the change that stopped treating a NIF as a WAKE_UP.

Restore the use of NIF as wakeup

[ChrisSFoot (Chris Foot)]

I have just installed the latest snapshot but am still having no luck getting the device initialised. The build is 2.0.0~20161014032924, however, doing list in karaf shows that the z-wave binding is version 2.0.0.201610131900 (which I think is before the issue mentioned was deal with, I have tried removing and reinstalling the z-wave binding but it still shows the same version. Is there any other way to force the binding to update? Alternatively, if the version showing isn’t important then what would be my next steps in troubleshooting the initialisation?

I’ve never managed to get any more than this listed for the item:

{
  "statusInfo": {
"status": "ONLINE",
"statusDetail": "NONE"
  },
  "label": "Z-Wave Node 5",
  "bridgeUID": "zwave:serial_zstick:95aa4fd4",
  "configuration": {
"wakeup_node": 0,
"wakeup_interval": 0
  },
  "properties": {
"zwave_class_basic": "ROUTING_SLAVE",
"zwave_class_generic": "BINARY_SENSOR",
"zwave_frequent": "false",
"zwave_neighbours": "1,2,3",
"zwave_nodeid": "5",
"zwave_version": "0.0",
"zwave_listening": "false",
"zwave_routing": "true",
"zwave_beaming": "true",
"zwave_class_specific": "ROUTING_SENSOR_BINARY"
  },
  "UID": "zwave:device:95aa4fd4:node5",
  "thingTypeUID": "zwave:device",
  "channels": []
}

Thanks

Chris

[jaydee73 (Stefan)]

You can try

bundle:update xxx (xxx is the zwave binding number)

on the karaf console.

This worked for me to get an update to the latest binding.

[Seaside]

@chris Could this be related to: Fibaro FGK 101 Missing temperature channel in openhab2? ?

@jaydee73 @ChrisSFoot
Think the 1013 version of the Z binding was what was included in the 1014 build.

bundle:list
197 | Active | 80 | 2.0.0.201610131900 | ZWave Binding
201 | Active | 80 | 1.9.0.201610140111 | openHAB MQTT Transport Bundle

bundle:update 197
Still gives the 2.0.0.201610131900

[ChrisSFoot (Chris Foot)]

I can confirm that I also still get the 201610131900 version when doing the bundle update. Useful command to know though! Much easier than removing and reinstalling it

[chris (Chris Jackson)]

@Seaside

Could this be related to:

I don’t know - really without a log it’s hard to say what is happening.

@Seaside

197 | Active | 80 | 2.0.0.201610131900 | ZWave Binding

It’s hard to understand what version this is. If I look on Cloudbees the last version was built at 2056 yesterday, which if timezones are correct was after I merged this change. Unfortunately the build dependancies don’t work any more, so I need to manually trigger the build after a merge and there’s no nightly build to catch this if I forget.

However, this doesn’t tie up with a binding time of 131900, so I don’t know what that is. The version before was at 1941, so maybe it’s this one, in which case it doesn’t have the NIF addition included.

I’ve just triggered another build which should be ready shortly.

[Seaside]

I can include and exclude the fibaro fgk 101 (Firmware 3.2).
I still don’t get any temperature readings, im using the 2.0.0.201610131900
Will try with the new build as well.

http://pastebin.com/92WGCLQc

I’m still missing temperature channel and I have attached another ds18b20 just to be sure.
I’ve excluded it. Reset it and readded it. But no success.
@Chris want debug logs for when I include it?

[chris (Chris Jackson)]

@Seaside

I’m still missing temperature channel and I have attached another ds18b20 just to be sure.

I don’t think this is included in the version you are running. I think that it was merged around 8PM last night, and your version is earlier than that. I triggered a new build this morning so it’s worth grabbing that.

NOte that you will also need to delete the thing and add it back again (not exclude/include) so that the binding picks up the latest definition.

[Seaside]

@chris

@Seaside

I’m still missing temperature channel and I have attached another ds18b20 just to be sure.

I don’t think this is included in the version you are running. I think that it was merged around 8PM last night, and your version is earlier than that. I triggered a new build this morning so it’s worth grabbing that.

NOte that you will also need to delete the thing and add it back again (not exclude/include) so that the binding picks up the latest definition.

Awsome! So my point is that at least for me it’s possible to Pair the fibaro fgk 101 firmware 3.2 with current openhab2/zwavebinding code. Not sure it’s helping in this case of paring troubles…

Regards S

[ChrisSFoot (Chris Foot)]

@chris

However, this doesn’t tie up with a binding time of 131900, so I don’t know what that is. The version before was at 1941, so maybe it’s this one, in which case it doesn’t have the NIF addition included.

I’ve just triggered another build which should be ready shortly.

I still can’t seem to get it to update. List still shows
233 | Active | 80 | 2.0.0.201610131900 | ZWave Binding

I should note that many of the other extensions (my.openhab, rest documentation, etc) also show this same version.

I’ve tried bundle:update and also uninstalling and reinstalling the binding. I also tried removing openhab entirely with apt-get remove and reinstalling but it still doesn’t want to give me a new version!

Doing dpkg -s openhab2-offline | grep Version gives me:

Version: 2.0.0~20161014032924
Config-Version: 2.0.0~20161014032924

So I am definitely running a newer snapshot of the main system! I’m clearly missing something.

[ChrisSFoot (Chris Foot)]

Ok, so I uninstalled the binding then manually removed the /var/lib/openhab2/tmp/mvn/org/openhab/binding/org.openhab.binding.zwave/ directory and reinstalled the binding and now it is running 2.0.0.201610140851.

I don’t yet know if the issue is sorted as i’m nowhere near the device to press the button but fingers crossed. It might be worth me mentioning that overnight last night I did see a wakeup event in the logs for the device but it still hadn’t completed initialisation this morning, that could just be because it needs more than one wakeup though!

[chris (Chris Jackson)]

It should be fine since the version this morning is exactly the same as before yesterdays version…

[Seaside]

@chris
I’m getting temperature readings now!
Thanks for the help and update!

Regards s

[chris (Chris Jackson)]

No problem - thanks for the feedback.

[ianj001 (IanJ)]

I am having the same issue that you were with getting the binding to update. I have tried everything that you have listed here and I am still not getting any update to the binding and I notice that a number of bindings appear to have older dates. Did you do anything else to get it to update?

I did notice when I delete /var/lib/openhab2/tmp/mvn/org/openhab/binding/org.openhab.binding.zwave if I do anything with the paperUI it appears again. I am not sure where this info is cached but I have tried removing the binding, removing this directory and restarting the machine but it still persists.

I can’t get the latest binding which I know is much later than my 2.1.0.201702121957 date that is showing up.
I have confirmed that the openhab core bundle is 2.1.0.201703171402 (today’s date).

UPDATE: The only way I could fix this was to purge openhab2 using apt then do a fresh install using the same sources and sure enough I got the latest binding.