OH2 Z-Wave refactoring and testing... and SECURITY

security
zwave
Tags: #<Tag:0x00007fd3131ddee8> #<Tag:0x00007fd3131ddda8>

(Kris K) #3236

I think this is it:


2018-07-10 21:25:00.756 [INFO ] [lipse.smarthome.model.script.Spotify] - Successfully got state from OpenHab: spotify_client_id
2018-07-10 21:25:28.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2018-07-10 21:25:28.090 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:meter_reset
2018-07-10 21:25:28.090 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2018-07-10 21:25:28.090 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:switch_dimmer1
2018-07-10 21:25:28.090 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
2018-07-10 21:25:28.091 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
2018-07-10 21:25:28.091 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_MULTILEVEL
2018-07-10 21:25:28.091 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
2018-07-10 21:25:28.091 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
2018-07-10 21:25:28.092 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-10 21:25:28.092 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2018-07-10 21:25:28.092 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-10 21:25:28.092 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:d4900ba9:node2:switch_dimmer1 on COMMAND_CLASS_BASIC
2018-07-10 21:25:28.092 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:meter_kwh1
2018-07-10 21:25:28.092 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-10 21:25:28.093 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-10 21:25:28.093 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
2018-07-10 21:25:28.093 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-10 21:25:28.093 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
2018-07-10 21:25:28.093 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
2018-07-10 21:25:28.094 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-10 21:25:28.094 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2018-07-10 21:25:28.094 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-10 21:25:28.094 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:d4900ba9:node2:meter_watts1
2018-07-10 21:25:28.094 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-10 21:25:28.094 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 2: Generating poll message for COMMAND_CLASS_METER, endpoint 1
2018-07-10 21:25:28.095 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Creating new message for application command METER_GET
2018-07-10 21:25:28.095 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_METER
2018-07-10 21:25:28.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 1
2018-07-10 21:25:28.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1
2018-07-10 21:25:28.095 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-10 21:25:28.096 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2018-07-10 21:25:28.096 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-10 21:25:28.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2018-07-10 21:25:28.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-10 21:25:28.096 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 02 06 60 0D 01 01 26 02 25 6A E3
2018-07-10 21:25:28.097 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0D 00 13 02 06 60 0D 01 01 26 02 25 6A E3
2018-07-10 21:25:28.097 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-10 21:25:28.097 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 124: Transaction Start type SendData
2018-07-10 21:25:28.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2018-07-10 21:25:28.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.098 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-10 21:25:28.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 124: [WAIT_RESPONSE] requiresResponse=true callback: 106
2018-07-10 21:25:28.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-10 21:25:28.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2018-07-10 21:25:28.100 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.105 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-10 21:25:28.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 124: [WAIT_RESPONSE] requiresResponse=true callback: 106
2018-07-10 21:25:28.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-10 21:25:28.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 124: [WAIT_RESPONSE] requiresResponse=true callback: 106
2018-07-10 21:25:28.106 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.106 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2018-07-10 21:25:28.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 124: Advanced to WAIT_REQUEST
2018-07-10 21:25:28.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 124: Transaction not completed
2018-07-10 21:25:28.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.121 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6A 00 00 02 83
2018-07-10 21:25:28.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 00 02
2018-07-10 21:25:28.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 00 02
2018-07-10 21:25:28.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 00 02
2018-07-10 21:25:28.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 124: [WAIT_REQUEST] requiresResponse=true callback: 106
2018-07-10 21:25:28.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-10 21:25:28.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 124: [WAIT_REQUEST] requiresResponse=true callback: 106
2018-07-10 21:25:28.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 124: (Callback 106)
2018-07-10 21:25:28.123 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-10 21:25:28.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 124: callback 106
2018-07-10 21:25:28.123 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 00 02
2018-07-10 21:25:28.124 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 106, Status = Transmission complete and ACK received(0)
2018-07-10 21:25:28.124 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-07-10 21:25:28.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 124: Advanced to WAIT_DATA
2018-07-10 21:25:28.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 124: Transaction not completed
2018-07-10 21:25:28.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.125 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.133 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 07 60 0D 01 01 26 03 2D 96
2018-07-10 21:25:28.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 07 60 0D 01 01 26 03 2D
2018-07-10 21:25:28.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 07 60 0D 01 01 26 03 2D
2018-07-10 21:25:28.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 07 60 0D 01 01 26 03 2D
2018-07-10 21:25:28.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-10 21:25:28.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2018-07-10 21:25:28.136 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-07-10 21:25:28.136 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2018-07-10 21:25:28.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
2018-07-10 21:25:28.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2018-07-10 21:25:28.137 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2018-07-10 21:25:28.137 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 45
2018-07-10 21:25:28.137 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-07-10 21:25:28.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 45
2018-07-10 21:25:28.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:switch_dimmer1 to 45 [PercentType]
2018-07-10 21:25:28.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2018-07-10 21:25:28.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18e09cb4.
2018-07-10 21:25:28.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18e09cb4.
2018-07-10 21:25:28.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:124 DONE
2018-07-10 21:25:28.140 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-10 21:25:28.141 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-10 21:25:28.141 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-10 21:25:28.141 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.141 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-10 21:25:28.141 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 32 01 00 25 6B F7
2018-07-10 21:25:28.142 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 32 01 00 25 6B F7
2018-07-10 21:25:28.142 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-10 21:25:28.142 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 125: Transaction Start type SendData
2018-07-10 21:25:28.143 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-10 21:25:28.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 125: [WAIT_RESPONSE] requiresResponse=true callback: 107
2018-07-10 21:25:28.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-10 21:25:28.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.150 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-10 21:25:28.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 125: [WAIT_RESPONSE] requiresResponse=true callback: 107
2018-07-10 21:25:28.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-10 21:25:28.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 125: [WAIT_RESPONSE] requiresResponse=true callback: 107
2018-07-10 21:25:28.151 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.151 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2018-07-10 21:25:28.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 125: Advanced to WAIT_REQUEST
2018-07-10 21:25:28.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 125: Transaction not completed
2018-07-10 21:25:28.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.166 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6B 00 00 02 82
2018-07-10 21:25:28.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=107, payload=6B 00 00 02
2018-07-10 21:25:28.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=107, payload=6B 00 00 02
2018-07-10 21:25:28.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=107, payload=6B 00 00 02
2018-07-10 21:25:28.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 125: [WAIT_REQUEST] requiresResponse=true callback: 107
2018-07-10 21:25:28.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-10 21:25:28.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 125: [WAIT_REQUEST] requiresResponse=true callback: 107
2018-07-10 21:25:28.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 125: (Callback 107)
2018-07-10 21:25:28.168 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-10 21:25:28.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 125: callback 107
2018-07-10 21:25:28.168 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=107, payload=6B 00 00 02
2018-07-10 21:25:28.168 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 107, Status = Transmission complete and ACK received(0)
2018-07-10 21:25:28.169 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-07-10 21:25:28.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 125: Advanced to WAIT_DATA
2018-07-10 21:25:28.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 125: Transaction not completed
2018-07-10 21:25:28.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.179 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 0A 00 00 D1
2018-07-10 21:25:28.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 0A 00 00
2018-07-10 21:25:28.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 0A 00 00
2018-07-10 21:25:28.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 60 0D 01 01 32 02 21 44 00 00 00 0A 00 00
2018-07-10 21:25:28.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-10 21:25:28.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2018-07-10 21:25:28.181 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-07-10 21:25:28.181 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2018-07-10 21:25:28.181 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_METER, endpoint 1
2018-07-10 21:25:28.182 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_METER
2018-07-10 21:25:28.182 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-07-10 21:25:28.182 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=kWh(0), Value=0.1
2018-07-10 21:25:28.182 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-07-10 21:25:28.182 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 0.1
2018-07-10 21:25:28.183 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:meter_kwh1 to 0.1 [DecimalType]
2018-07-10 21:25:28.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2018-07-10 21:25:28.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@468c30ec.
2018-07-10 21:25:28.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@468c30ec.
2018-07-10 21:25:28.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:125 DONE
2018-07-10 21:25:28.189 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-10 21:25:28.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-10 21:25:28.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-10 21:25:28.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-10 21:25:28.190 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 32 01 10 25 6C E0
2018-07-10 21:25:28.190 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 32 01 10 25 6C E0
2018-07-10 21:25:28.191 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-10 21:25:28.191 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 126: Transaction Start type SendData
2018-07-10 21:25:28.192 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-10 21:25:28.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-10 21:25:28.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 126: [WAIT_RESPONSE] requiresResponse=true callback: 108
2018-07-10 21:25:28.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-10 21:25:28.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.199 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-10 21:25:28.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 126: [WAIT_RESPONSE] requiresResponse=true callback: 108
2018-07-10 21:25:28.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-10 21:25:28.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 126: [WAIT_RESPONSE] requiresResponse=true callback: 108
2018-07-10 21:25:28.200 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-10 21:25:28.200 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2018-07-10 21:25:28.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 126: Advanced to WAIT_REQUEST
2018-07-10 21:25:28.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 126: Transaction not completed
2018-07-10 21:25:28.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.215 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6C 00 00 02 85
2018-07-10 21:25:28.215 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=108, payload=6C 00 00 02
2018-07-10 21:25:28.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=108, payload=6C 00 00 02
2018-07-10 21:25:28.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=108, payload=6C 00 00 02
2018-07-10 21:25:28.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 126: [WAIT_REQUEST] requiresResponse=true callback: 108
2018-07-10 21:25:28.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-10 21:25:28.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 126: [WAIT_REQUEST] requiresResponse=true callback: 108
2018-07-10 21:25:28.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 126: (Callback 108)
2018-07-10 21:25:28.217 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-10 21:25:28.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 126: callback 108
2018-07-10 21:25:28.217 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=108, payload=6C 00 00 02
2018-07-10 21:25:28.217 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 108, Status = Transmission complete and ACK received(0)
2018-07-10 21:25:28.217 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-07-10 21:25:28.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 126: Advanced to WAIT_DATA
2018-07-10 21:25:28.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 126: Transaction not completed
2018-07-10 21:25:28.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-10 21:25:28.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-10 21:25:28.228 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 12 00 04 00 02 0C 60 0D 01 01 32 02 21 32 00 8A 00 00 23
2018-07-10 21:25:28.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0C 60 0D 01 01 32 02 21 32 00 8A 00 00
2018-07-10 21:25:28.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0C 60 0D 01 01 32 02 21 32 00 8A 00 00
2018-07-10 21:25:28.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0C 60 0D 01 01 32 02 21 32 00 8A 00 00
2018-07-10 21:25:28.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-10 21:25:28.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2018-07-10 21:25:28.229 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-07-10 21:25:28.230 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2018-07-10 21:25:28.230 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_METER, endpoint 1
2018-07-10 21:25:28.230 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_METER
2018-07-10 21:25:28.230 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-07-10 21:25:28.230 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=13.8
2018-07-10 21:25:28.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-07-10 21:25:28.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 13.8
2018-07-10 21:25:28.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:d4900ba9:node2:meter_watts1 to 13.8 [DecimalType]


(Chris Jackson) #3237

Thanks. So what this shows is that the update is due to polling - not unsolicited data from the device (ie from the associations).

In the above log we see the binding is sending out a GET request, so this is associated with polling. In the log, we also see NODE 2: Polling... so this also confirms this.

This likely means that the association lifeline group is likely not set?


(Aaron) #3238

Are there any known issues with channels that use configuration command class? I’m asking because of this topic: Z-Wave Binding Issues with Channels Using COMMAND_CLASS_CONFIGURATION


(Kris K) #3239

Hi chris as per a post you made about your binding i set the association group for lifeline to be ‘openhab controller’ using habmin


(Kris K) #3240

See screenshot, is there anything else needed from an association PoV?


(Kris K) #3241

kris@OpenHAB:~$ sudo cat /var/log/openhab2/openhab.log | grep association
2018-07-10 21:19:01.207 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Current Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[]]
2018-07-10 21:19:01.208 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: New Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1_                               1]]
2018-07-10 21:19:01.359 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 2: association group 1 has max associations 1
2018-07-10 21:19:10.953 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Current Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[]]
2018-07-10 21:19:10.954 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: New Members ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1_                               1]]
2018-07-10 21:19:11.039 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 4: association group 1 has max associations 1


(Chris Jackson) #3242

A full debug log from the initialisation is probably the best thing. The snippits from above aren’t really that helpful to work out what’s going on (sorry).

One thing you could try is to exclude the device and add it back again. This would reset it and it might then sort out the problem since I think when you added this initially it was using the master binding?


(Kris K) #3243

Correct Chris, ill do that now


(Kris K) #3245

https://drive.google.com/file/d/1SmWAD0WOeKtf4bDYFGqC-BKkEwsmZUAZ/view?usp=sharing

Repairing log @chris


(geir) #3246

Tried searching this thread but didn’t find anything usefull on the matter.

Just returned to try out openhab again and installed everything in the 2.3 setup with default z-wave binding, tought i should test out the refactored edition.

After “readding” all the things(as the first post says) it seems lik the openhab doesn’t get updates anymore, but i can push commands from openhab to zwave devices.

Confirmed Openhab is listed in life on the tested units.


(Matt) #3247

I installed as described in the first post. The two garage door openers and deadbolt lock added seemingly ok, in that they aren’t “unknown devices” anymore. However they’re not working. Here’s what’s in the log:

2018-07-12 14:51:08.936 [INFO ] [alization.ZWaveNodeInitStageAdvancer] - NODE 36: SECURITY_INC State=FAILED, Reason=SECURE_PING

2018-07-12 14:51:13.963 [INFO ] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: SECURITY_INC State=FAILED, Reason=SECURE_PING

2018-07-12 14:58:18.343 [INFO ] [alization.ZWaveNodeInitStageAdvancer] - NODE 35: SECURITY_INC State=FAILED, Reason=SECURE_PING

2018-07-12 15:14:44.384 [WARN ] [nal.converter.ZWaveDoorLockConverter] - NODE 36: Command class COMMAND_CLASS_DOOR_LOCK not found

2018-07-12 15:14:51.950 [WARN ] [nal.converter.ZWaveDoorLockConverter] - NODE 36: Command class COMMAND_CLASS_DOOR_LOCK not found[


(Chris Jackson) #3248

Did you exclude these devices and re-include them? Since you are trying to use security, if they were previously included, they must be reset before trying to securely include them.


(Dan) #3249

Hi Chris,

Since I started with the 4 July version of the experimental binding I’ve had lots of devices show up as offline - wired as well as battery powered. Haven’t seen this before.

I don’t suppose you know if this is a known issue, or is more likely a hardware problem with my zstick?

Dan


(Chris Jackson) #3250

Hi Dan,
Yes, it’s sort of known - at least for battery devices the change of DEAD node handling has not worked so well. It’s a little strange as the change was very minor, but it does seem to impact large networks.

I’m happy if you want to send me more logs - I know there’s an issue with battery queue management, but I’m surprised you have problems with powered devices…

Cheers
Chris


(Dan) #3251

many thanks - right now everything seems online again… I’ll wait for a time when some devices have gone offline and send you the logs then.


(Chris Jackson) #3252

Thanks- feel free to attach to the last log ticket - might help keep it in one place.


(Matt) #3253

Many times. It wasn’t until I stumbled across a post in here that you have to use habmini’s inclusion mode for security enabled devices. I was just using the z-stick button before. Once I excluded and included using the UI, all three security enabled devices came to life. So with that, all my devices are now working properly! Thanks!


(Chris Jackson) #3254

I can recommend reading the documentation :wink:

Secure inclusion must be started from the binding directly (ie with the controller plugged in to the USB and Online*). This is because once the device is included into the network, a key exchange takes place between the binding and the device. This key exchange must take place within a very short time of the inclusion, and if it doesn’t succeed, the device must be excluded and included again. Secure inclusion will generate a lot of activity on the network, so you should avoid other activities at the same time, and the device being included should be close to the controller to reduce any retries that could cause the security handshake to fail.


(Matt) #3255

I stopped reading instructions about 20 years ago :slight_smile:


( -) #3256

Hey Guys… I am running the latest 20180707 build, and by accident managed to hit “Hard Reset Controller” instead of “Exclude devices”… Never ever use an iPad to do this…

But I keep on seeing a few

2018-07-13 15:38:18.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling…
2018-07-13 15:38:18.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling deferred until initialisation complete

Is all hope lost?
EDIT:
And if so - any tips on how to go about including them all (100 devices) again?