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?