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

If we remove it when the thing is deleted, but the device is not excluded, then when it’s added back, there will be more initialisation required. Sometimes this might be a good thing, but often it’s just more noise on the network.

I’m in two minds about it, but when I was implementing the change I decided to keep the two decoupled as the XML really sits in the protocol ‘half’ of the binding.

Feel free to try and convince me though if you think it’s not the right choice… :slight_smile:

For me it is not so easy to see so I post the seconds before and after the Stopp here. Maybe you can see something in it?






2018-07-15 20:31:17.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-15 20:31:17.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 519: [WAIT_REQUEST] requiresResponse=true callback: 4
2018-07-15 20:31:17.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 519: (Callback 4)
2018-07-15 20:31:17.903 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-15 20:31:17.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 519: callback 4
2018-07-15 20:31:17.904 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 21 
2018-07-15 20:31:17.904 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 52: SendData Request. CallBack ID = 4, Status = Transmission complete and ACK received(0)
2018-07-15 20:31:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 519: Advanced to WAIT_DATA
2018-07-15 20:31:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 52: TID 519: Transaction not completed
2018-07-15 20:31:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-15 20:31:17.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1cb077fa
2018-07-15 20:31:17.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Adding to device queue
2018-07-15 20:31:17.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true
2018-07-15 20:31:17.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-15 20:31:17.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 209ms
2018-07-15 20:31:17.993 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 05 00 00 1B F5 
2018-07-15 20:31:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 1B 
2018-07-15 20:31:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 1B 
2018-07-15 20:31:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 1B 
2018-07-15 20:31:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] requiresResponse=true callback: 5
2018-07-15 20:31:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 533: [WAIT_REQUEST] requiresResponse=true callback: 5
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 533: (Callback 5)
2018-07-15 20:31:17.999 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 533: callback 5
2018-07-15 20:31:17.999 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 1B 
2018-07-15 20:31:17.999 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 131: SendData Request. CallBack ID = 5, Status = Transmission complete and ACK received(0)
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 533: Advanced to WAIT_DATA
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: TID 533: Transaction not completed
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:17.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-15 20:31:18.129 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5D 0A 71 05 00 00 00 FF 07 00 01 08 39 
2018-07-15 20:31:18.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=93, callback=0, payload=00 5D 0A 71 05 00 00 00 FF 07 00 01 08 
2018-07-15 20:31:18.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=93, callback=0, payload=00 5D 0A 71 05 00 00 00 FF 07 00 01 08 
2018-07-15 20:31:18.131 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=93, callback=0, payload=00 5D 0A 71 05 00 00 00 FF 07 00 01 08 
2018-07-15 20:31:18.131 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-15 20:31:18.131 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 93: Application Command Request (ALIVE:REQUEST_NIF)
2018-07-15 20:31:18.131 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 93: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2018-07-15 20:31:18.131 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 93: SECURITY NOT required on COMMAND_CLASS_ALARM
2018-07-15 20:31:18.132 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 93: Received COMMAND_CLASS_ALARM V5 NOTIFICATION_REPORT
2018-07-15 20:31:18.132 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 93: NOTIFICATION report - 0 = 0, event=0, status=255, plen=1
2018-07-15 20:31:18.132 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 93: Alarm Type = BURGLAR (0)
2018-07-15 20:31:18.132 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 93: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2018-07-15 20:31:18.132 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 93: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 255
2018-07-15 20:31:18.132 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
2018-07-15 20:31:18.133 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 83 03 30 03 00 41 
2018-07-15 20:31:18.133 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 0, type OnOffType
2018-07-15 20:31:18.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 93: Updating channel state zwave:device:ZWUG:node93:alarm_motion to OFF [OnOffType]
2018-07-15 20:31:18.135 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
2018-07-15 20:31:18.135 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 0, type OnOffType
2018-07-15 20:31:18.136 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 93: Updating channel state zwave:device:ZWUG:node93:alarm_tamper to OFF [OnOffType]
2018-07-15 20:31:18.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=131, callback=0, payload=00 83 03 30 03 00 
2018-07-15 20:31:18.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=131, callback=0, payload=00 83 03 30 03 00 
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 93: Commands processed 1.
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 93: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@74d1bcb3.
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 93: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@74d1bcb3.
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:18.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-15 20:31:18.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=131, callback=0, payload=00 83 03 30 03 00 
2018-07-15 20:31:18.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-15 20:31:18.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-07-15 20:31:18.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 131: Incoming command class COMMAND_CLASS_SENSOR_BINARY, endpoint 0
2018-07-15 20:31:18.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 131: SECURITY not supported
2018-07-15 20:31:18.139 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 131: Received COMMAND_CLASS_SENSOR_BINARY V1 SENSOR_BINARY_REPORT
2018-07-15 20:31:18.139 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 131: Sensor Binary report, type=Unknown, value=0
2018-07-15 20:31:18.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 131: Got an event from Z-Wave network: ZWaveBinarySensorValueEvent
2018-07-15 20:31:18.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 131: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_BINARY, value = 0
2018-07-15 20:31:18.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 131: Updating channel state zwave:device:ZWOG:node131:sensor_binary to OFF [OnOffType]
2018-07-15 20:31:18.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: Commands processed 1.
2018-07-15 20:31:18.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f5821a7.
2018-07-15 20:31:18.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f5821a7.
2018-07-15 20:31:18.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: notifyTransactionResponse TID:533 DONE
2018-07-15 20:31:18.143 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 131: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-15 20:31:18.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-15 20:31:18.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-15 20:31:18.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:18.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-15 20:31:18.144 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9E 02 26 02 25 07 7F 
2018-07-15 20:31:18.144 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 158: Sending REQUEST Message = 01 09 00 13 9E 02 26 02 25 07 7F 
2018-07-15 20:31:18.150 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-15 20:31:18.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-15 20:31:18.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-15 20:31:18.155 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-15 20:31:18.156 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 534: Transaction Start type SendData 
2018-07-15 20:31:18.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-15 20:31:18.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 534: [WAIT_RESPONSE] requiresResponse=true callback: 7
2018-07-15 20:31:18.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-15 20:31:18.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:18.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-15 20:31:18.158 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-07-15 20:31:18.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-15 20:31:18.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-15 20:31:18.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-15 20:31:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 534: [WAIT_RESPONSE] requiresResponse=true callback: 7
2018-07-15 20:31:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-15 20:31:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 534: [WAIT_RESPONSE] requiresResponse=true callback: 7
2018-07-15 20:31:18.168 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-15 20:31:18.168 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 158: sentData successfully placed on stack.
2018-07-15 20:31:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 534: Advanced to WAIT_REQUEST
2018-07-15 20:31:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 158: TID 534: Transaction not completed
2018-07-15 20:31:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:18.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-15 20:31:18.174 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Holdoff Timer triggered...
2018-07-15 20:31:18.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-15 20:31:18.177 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 1E 85 
2018-07-15 20:31:18.177 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 1E 85 
2018-07-15 20:31:18.182 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-15 20:31:18.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-15 20:31:18.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-15 20:31:18.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-15 20:31:18.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-15 20:31:18.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-15 20:31:18.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:18.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-15 20:31:18.184 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-15 20:31:18.184 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 00 9A 
2018-07-15 20:31:18.185 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 536: Transaction Start type RequestNodeInfo 
2018-07-15 20:31:18.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2018-07-15 20:31:18.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2018-07-15 20:31:18.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2018-07-15 20:31:18.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 536: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-15 20:31:18.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-15 20:31:18.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 536: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-15 20:31:18.186 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2018-07-15 20:31:18.186 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2018-07-15 20:31:18.187 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 536: Transaction CANCELLED
2018-07-15 20:31:18.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-07-15 20:31:18.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 533: Transaction event listener: DONE: DONE -> 
2018-07-15 20:31:18.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 131: -- To notify -- COMPLETE
2018-07-15 20:31:18.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 533 --
2018-07-15 20:31:18.197 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@4885c047
2018-07-15 20:31:18.197 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node Init transaction completed with response COMPLETE
2018-07-15 20:31:18.197 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ZWAVEPLUS_INFO
2018-07-15 20:31:18.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_BASIC
2018-07-15 20:31:18.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SWITCH_MULTILEVEL
2018-07-15 20:31:18.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Found 0 instances of COMMAND_CLASS_SWITCH_MULTILEVEL for endpoint 0
2018-07-15 20:31:18.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node advancer: Initialisation complete!
2018-07-15 20:31:18.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node advancer - advancing to DYNAMIC_END
2018-07-15 20:31:18.198 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 131: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-07-15 20:31:18.198 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 131: Serializing to file C:\OH240_~1\userdata\zwave\network_d763b7a3__node_131.xml
2018-07-15 20:31:18.224 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 131: Node advancer - advancing to DONE
2018-07-15 20:31:18.224 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 131: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-07-15 20:31:18.224 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 131: Serializing to file C:\OH240_~1\userdata\zwave\network_d763b7a3__node_131.xml
2018-07-15 20:31:18.347 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 07 00 00 14 F8 
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 14 
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 14 
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 14 
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 534: [WAIT_REQUEST] requiresResponse=true callback: 7
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 534: [WAIT_REQUEST] requiresResponse=true callback: 7
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 534: (Callback 7)
2018-07-15 20:31:18.349 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 534: callback 7
2018-07-15 20:31:18.349 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 14 
2018-07-15 20:31:18.349 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 158: SendData Request. CallBack ID = 7, Status = Transmission complete and ACK received(0)
2018-07-15 20:31:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 534: Advanced to WAIT_DATA
2018-07-15 20:31:18.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 158: TID 534: Transaction not completed
2018-07-15 20:31:18.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:18.523 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 9E 03 26 03 63 29 
2018-07-15 20:31:18.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=158, callback=0, payload=00 9E 03 26 03 63 
2018-07-15 20:31:18.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=158, callback=0, payload=00 9E 03 26 03 63 
2018-07-15 20:31:18.794 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:31:18.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:31:18.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:31:18.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:31:18.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-15 20:31:18.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 91: Application Command Request (ALIVE:PING)
2018-07-15 20:31:18.797 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 91: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2018-07-15 20:31:18.797 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 91: SECURITY not supported
2018-07-15 20:31:18.797 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 91: Received COMMAND_CLASS_ALARM V3 NOTIFICATION_REPORT
2018-07-15 20:31:18.797 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 91: NOTIFICATION report - 0 = 0, event=3, status=255, plen=0
2018-07-15 20:31:18.797 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 91: Alarm Type = BURGLAR (0)
2018-07-15 20:31:18.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 91: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2018-07-15 20:31:18.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 91: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 255
2018-07-15 20:31:18.797 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
2018-07-15 20:31:18.797 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 3, type OnOffType
2018-07-15 20:31:18.797 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
2018-07-15 20:31:18.798 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 3, type OnOffType
2018-07-15 20:31:18.798 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 91: Updating channel state zwave:device:ZWUG:node91:alarm_tamper to ON [OnOffType]
2018-07-15 20:31:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 91: Commands processed 1.
2018-07-15 20:31:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 91: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a6623f4.
2018-07-15 20:31:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 91: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a6623f4.
2018-07-15 20:31:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-15 20:31:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-07-15 20:31:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-15 20:31:20.553 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 00 1B FD 00 00 00 00 00 00 00 00 00 00 7D 
2018-07-15 20:31:20.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 1B FD 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:31:20.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 1B FD 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:31:21.354 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:31:21.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:31:21.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:31:21.680 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 37 03 20 03 FF 1A 
2018-07-15 20:31:21.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=55, callback=0, payload=00 37 03 20 03 FF 
2018-07-15 20:31:21.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=55, callback=0, payload=00 37 03 20 03 FF 
2018-07-15 20:31:21.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1f42efc8
2018-07-15 20:31:21.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Bump transaction 395 priority from Controller to Immediate
2018-07-15 20:31:21.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Adding to device queue
2018-07-15 20:31:22.079 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 24 12 32 02 21 64 00 00 DD 4B 02 58 00 00 DD 4A 00 00 00 00 FB 
2018-07-15 20:31:22.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=36, callback=0, payload=00 24 12 32 02 21 64 00 00 DD 4B 02 58 00 00 DD 4A 00 00 00 00 
2018-07-15 20:31:22.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=36, callback=0, payload=00 24 12 32 02 21 64 00 00 DD 4B 02 58 00 00 DD 4A 00 00 00 00 
2018-07-15 20:31:22.666 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 27: ZWaveCommandClassTransactionPayload - send to node
2018-07-15 20:31:22.666 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: Encapsulating message, endpoint 0
2018-07-15 20:31:22.666 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: SECURITY not supported
2018-07-15 20:31:22.666 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: Command Class COMMAND_CLASS_METER is NOT required to be secured
2018-07-15 20:31:22.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1aeff4f2
2018-07-15 20:31:23.544 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 5D 09 71 05 00 00 00 FF 07 08 00 24 
2018-07-15 20:31:23.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 3<>125 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=93, callback=0, payload=00 5D 09 71 05 00 00 00 FF 07 08 00 
2018-07-15 20:31:23.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=93, callback=0, payload=00 5D 09 71 05 00 00 00 FF 07 08 00 

Two of four Minimotes came up OK after deleting their Things (and XMLs for good measure?) and restarting OH. The two that are not working have completed initialization, but are missing WAKEUP and SCENE_ACTIVATION in their XMLs, where the others have them. I’ve deleted them a few times now with no change. Is it time for logs?

Yes - probably worth a look…

I truly hate these Minimotes. I wish I had never bought them! :angry:

I think this is caused by a synchronisation issue related to the holdoff timer. I’ve given it a bit of a tidy up - please try the latest version to see if it’s any better.

Thanks.

Hopefully this is now resolved…

That worked perfectly… thank you! Didn’t even have to delete the Things!

1 Like

Alright, so I’ve added all of my devices again using Z-Way server after that unfortunate factory reset, transferred the SecurityKey to the Binding (although in small letters instead of capital).

Before shutting down Z-Way server I made sure and helped some devices reach 100% initialization.

What’s the difference between items called:
Z-Wave Node 058
and
Z-Wave Node 053: FGK101 Door Opening Sensor

They are both the same model.
Will the Node 058 change name after the initialization process (and therefore I should wait for it to change in the Inbox?)

Could this be due to the wrong SecurityKey? (Small letters)

Probably nothing. I’ve seen devices discovered both ways. I suspect it has to do with how the inbox entry and/or Thing are updated throughout the initialization process.

It might, and it might not. :roll_eyes:

Yes - if the information is available (ie the initialisation has completed enough) then the name is added to the node. If not, it’s just the node number.

If it’s still in the inbox, it should update the inbox entry. If you have already created a thing before the initialisation completes, then it won’t change the name of the thing…

Which, now that you explain it, makes perfect sense. Helps avoid the case where the binding overwrites a change I made to the name of the Thing. :ok_hand:

Edit: Which also explains why I tend to see this behavior more often with battery devices (due to the time it can take to initialize).

And just to confirm that the new version continues to be much much much more robust.

1 Like

Hey @chris
What happens, if I sends an configuration update to a battery driven zwave device. The device will receive the update, when it wakes up, correct?
What if I reboot the Openhab system in between. Will the update still go through anyway or is it lost and have to be send again?

Correct. The command is stored in a queue until the device wakes.

The queue is not persisted, so it will be lost and you will need to send it again.

Then I found the reason why some of my devices didn´t update the other day… Nice to know :slight_smile:

Anyone with a Kwikset door lock have quick drain of their battery? I can only get about 3 - 4 weeks on my door lock battery when I have zwave enabled on the lock and paired with OH. When I unpair the lock it goes for significantly more time.

I had one of these (the operative word is had). I can’t remember the model number. I was getting a couple weeks of life out of a set of batteries. Was driving me nuts.

Have you checked the polling interval. Maybe set it to something very long – maybe 2 days or 10 days.

I would second this. I have two networks – one with about a dozen nodes and one with almost 70. Both networks are running very, very well.

@chris Notwithstanding the change we discussed last night, from my perspective, this version looks like something that’s about ready to replace the current master version. Again, from my perspective, this version is at least as stable (if not more stable) than the current master, AND it supports security, AND it has a working heal process that runs nightly.

1 Like

I think I have a solution to this…

Thanks Mark.

@5iver - hows your milage looking these days?