Some debug output:
2016-09-17 16:27:45.062 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.077 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 03 00 00 02 EA
2016-09-17 16:27:45.078 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.079 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 00 00 02 00 00 E4
2016-09-17 16:27:45.079 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 03 00 00 02 00 00 E4
2016-09-17 16:27:45.080 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=03 00 00 02
2016-09-17 16:27:45.080 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 3, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Node is ALIVE. Init stage is PING.
2016-09-17 16:27:45.081 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2016-09-17 16:27:45.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2016-09-17 16:27:45.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting ONLINE
2016-09-17 16:27:45.082 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Status event during initialisation - Node is ALIVE
2016-09-17 16:27:45.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: queue length(1), free to send(false)
2016-09-17 16:27:45.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 10000
2016-09-17 16:27:45.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2016-09-17 16:27:45.083 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2016-09-17 16:27:45.084 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is ALIVE
2016-09-17 16:27:45.084 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=2, callback=3, payload=02 01 00
2016-09-17 16:27:45.085 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=03 00 00 02
2016-09-17 16:27:45.085 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=3, expected=SendData, cancelled=false transaction complete!
2016-09-17 16:27:45.085 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.085 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
2016-09-17 16:27:45.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PING: queue length(0), free to send(true)
2016-09-17 16:27:45.087 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 10000
2016-09-17 16:27:45.087 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PING try 2: stageAdvanced(false)
2016-09-17 16:27:45.087 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to DETAILS
2016-09-17 16:27:45.087 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-17 16:27:45.088 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-17 16:27:45.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2016-09-17 16:27:45.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Restored from file - skipping static initialisation
2016-09-17 16:27:45.088 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to GET_CONFIGURATION
2016-09-17 16:27:45.088 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-17 16:27:45.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-17 16:27:45.089 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - GET_CONFIGURATION try 0: stageAdvanced(true)
2016-09-17 16:27:45.091 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - thing is null!
2016-09-17 16:27:45.092 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to DYNAMIC_VALUES
2016-09-17 16:27:45.092 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-09-17 16:27:45.092 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-09-17 16:27:45.092 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - DYNAMIC_VALUES try 0: stageAdvanced(true)
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking SWITCH_ALL
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking CONFIGURATION
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking METER
2016-09-17 16:27:45.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found METER
2016-09-17 16:27:45.094 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of METER
2016-09-17 16:27:45.094 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
2016-09-17 16:27:45.095 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
2016-09-17 16:27:45.095 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2016-09-17 16:27:45.096 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.096 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking ASSOCIATION
2016-09-17 16:27:45.096 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking PROTECTION
2016-09-17 16:27:45.096 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found PROTECTION
2016-09-17 16:27:45.097 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of PROTECTION
2016-09-17 16:27:45.097 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 2: Creating new message for command PROTECTION_GET
2016-09-17 16:27:45.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking POWERLEVEL
2016-09-17 16:27:45.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found POWERLEVEL
2016-09-17 16:27:45.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of POWERLEVEL
2016-09-17 16:27:45.098 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 2: Creating new message for application command POWERLEVEL_GET
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking BASIC
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking VERSION
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2016-09-17 16:27:45.099 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking SENSOR_MULTILEVEL
2016-09-17 16:27:45.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found SENSOR_MULTILEVEL
2016-09-17 16:27:45.100 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of SENSOR_MULTILEVEL
2016-09-17 16:27:45.100 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Creating new message for command SENSOR_MULTI_LEVEL_GET
2016-09-17 16:27:45.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - checking SWITCH_BINARY
2016-09-17 16:27:45.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - found SWITCH_BINARY
2016-09-17 16:27:45.101 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Found 1 instances of SWITCH_BINARY
2016-09-17 16:27:45.102 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_GET
2016-09-17 16:27:45.102 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: DYNAMIC_VALUES - queued 6 frames
2016-09-17 16:27:45.103 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 52ms/173ms.
2016-09-17 16:27:45.103 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.103 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 32 01 10 25 0C ED
2016-09-17 16:27:45.104 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 32 01 10 25 0C ED
2016-09-17 16:27:45.113 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.113 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.114 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-09-17 16:27:45.115 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.115 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-09-17 16:27:45.116 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.129 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0C 00 00 02 E5
2016-09-17 16:27:45.130 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.131 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0C 00 00 02 00 00 EB
2016-09-17 16:27:45.131 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 0C 00 00 02 00 00 EB
2016-09-17 16:27:45.132 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0C 00 00 02
2016-09-17 16:27:45.132 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 12, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.133 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=12, payload=02 03 32 01 10
2016-09-17 16:27:45.133 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0C 00 00 02
2016-09-17 16:27:45.134 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=12, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2016-09-17 16:27:45.141 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 02 0A 32 02 21 14 00 00 00 00 00 00 E6
2016-09-17 16:27:45.143 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.143 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 02 0A 32 02 21 14 00 00 00 00 00 00 E6
2016-09-17 16:27:45.144 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 02 0A 32 02 21 14 00 00 00 00 00 00 E6
2016-09-17 16:27:45.144 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0A 32 02 21 14 00 00 00 00 00 00
2016-09-17 16:27:45.144 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-09-17 16:27:45.145 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class METER
2016-09-17 16:27:45.145 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Received METER command V2
2016-09-17 16:27:45.147 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2016-09-17 16:27:45.147 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2016-09-17 16:27:45.147 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2016-09-17 16:27:45.148 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0E+1
2016-09-17 16:27:45.148 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=12, payload=02 03 32 01 10
2016-09-17 16:27:45.149 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0A 32 02 21 14 00 00 00 00 00 00
2016-09-17 16:27:45.149 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=12, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-09-17 16:27:45.149 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.149 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.149 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 6.
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 5.
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: queue length(5), free to send(true)
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 5000
2016-09-17 16:27:45.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 5
2016-09-17 16:27:45.150 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.151 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 47ms/173ms.
2016-09-17 16:27:45.151 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.151 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 32 01 00 25 0D FC
2016-09-17 16:27:45.151 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 32 01 00 25 0D FC
2016-09-17 16:27:45.161 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.162 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.162 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-09-17 16:27:45.163 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.164 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-09-17 16:27:45.164 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.177 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0D 00 00 02 E4
2016-09-17 16:27:45.178 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.179 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0D 00 00 02 00 00 EA
2016-09-17 16:27:45.179 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 0D 00 00 02 00 00 EA
2016-09-17 16:27:45.180 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0D 00 00 02
2016-09-17 16:27:45.181 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 13, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.182 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=13, payload=02 03 32 01 00
2016-09-17 16:27:45.183 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0D 00 00 02
2016-09-17 16:27:45.183 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=13, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2016-09-17 16:27:45.191 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 4C
2016-09-17 16:27:45.192 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.193 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 14 00 04 00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 4C
2016-09-17 16:27:45.193 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 14 00 04 00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00 4C
2016-09-17 16:27:45.194 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00
2016-09-17 16:27:45.194 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-09-17 16:27:45.195 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class METER
2016-09-17 16:27:45.195 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Received METER command V2
2016-09-17 16:27:45.196 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=kWh(0), Value=0.00001
2016-09-17 16:27:45.197 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2016-09-17 16:27:45.197 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2016-09-17 16:27:45.197 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.00001
2016-09-17 16:27:45.198 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=13, payload=02 03 32 01 00
2016-09-17 16:27:45.198 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 0E 32 02 21 A4 00 00 00 01 0C 17 00 00 00 00
2016-09-17 16:27:45.199 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=13, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-09-17 16:27:45.199 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.199 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.199 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 5.
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 4.
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: queue length(4), free to send(true)
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 5000
2016-09-17 16:27:45.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 4
2016-09-17 16:27:45.201 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.201 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 49ms/173ms.
2016-09-17 16:27:45.201 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.202 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 75 02 25 0E B9
2016-09-17 16:27:45.202 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 75 02 25 0E B9
2016-09-17 16:27:45.211 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.212 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.212 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-09-17 16:27:45.213 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.214 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-09-17 16:27:45.214 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-09-17 16:27:45.227 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0E 00 00 02 E7
2016-09-17 16:27:45.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.229 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0E 00 00 02 00 00 E9
2016-09-17 16:27:45.230 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 0E 00 00 02 00 00 E9
2016-09-17 16:27:45.230 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0E 00 00 02
2016-09-17 16:27:45.230 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 14, Status = Transmission complete and ACK received(0)
2016-09-17 16:27:45.231 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=14, payload=02 02 75 02
2016-09-17 16:27:45.231 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=0E 00 00 02
2016-09-17 16:27:45.231 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=14, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2016-09-17 16:27:45.238 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 75 03 00 85
2016-09-17 16:27:45.239 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.240 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 02 03 75 03 00 85
2016-09-17 16:27:45.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 02 03 75 03 00 85
2016-09-17 16:27:45.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 75 03 00
2016-09-17 16:27:45.242 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-09-17 16:27:45.242 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class PROTECTION
2016-09-17 16:27:45.243 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 2: Received PROTECTION command V1
2016-09-17 16:27:45.243 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2016-09-17 16:27:45.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2016-09-17 16:27:45.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = PROTECTION, value = UNPROTECTED
2016-09-17 16:27:45.244 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 2: Received protection report local:UNPROTECTED
2016-09-17 16:27:45.245 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=14, payload=02 02 75 02
2016-09-17 16:27:45.245 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 75 03 00
2016-09-17 16:27:45.246 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=14, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-09-17 16:27:45.246 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.246 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-09-17 16:27:45.246 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 4.
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 3.
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - DYNAMIC_VALUES: queue length(3), free to send(true)
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Initialisation retry timer started 5000
2016-09-17 16:27:45.247 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 3
2016-09-17 16:27:45.248 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2016-09-17 16:27:45.248 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 46ms/173ms.
2016-09-17 16:27:45.248 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2016-09-17 16:27:45.249 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 73 02 25 0F BE
2016-09-17 16:27:45.249 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 73 02 25 0F BE
2016-09-17 16:27:45.258 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-09-17 16:27:45.259 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-17 16:27:45.260 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
(I had to shorten it, but some communication take clearly place)