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

chris · July 10, 2018, 11:50am

Yes - if you send a command to the dimmer, it should change immediately. Is that not happening? I thought that controlling the device was ok, but it’s just the meter readings you weren’t receiving?

dastrix80 · July 10, 2018, 12:00pm

Sorry Chris, yes controlling the device is faultless. Meter readings are problematic. They work, just slowly. I tried changing my settings to be aggressive for what relates to power reports, the issue remains.

chris · July 10, 2018, 12:09pm

In the last log you show a meter report - can you provide 10 seconds of data from immediately before this log entry?

dastrix80 · July 10, 2018, 12:13pm

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 · July 10, 2018, 12:39pm

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?

Aaron23 · July 10, 2018, 7:57pm

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

dastrix80 · July 10, 2018, 8:01pm

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

dastrix80 · July 10, 2018, 8:27pm

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

dastrix80 · July 10, 2018, 8:31pm


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 · July 10, 2018, 8:41pm

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?

dastrix80 · July 10, 2018, 8:52pm

Correct Chris, ill do that now

dastrix80 · July 10, 2018, 9:30pm

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

Repairing log @chris

labanx · July 12, 2018, 7:01am

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.

Pedals2Paddles · July 12, 2018, 7:20pm

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 · July 13, 2018, 7:18am

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.

dan12345 · July 13, 2018, 11:03am

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 · July 13, 2018, 12:04pm

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

dan12345 · July 13, 2018, 12:41pm

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 · July 13, 2018, 12:42pm

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

Pedals2Paddles · July 13, 2018, 12:44pm

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!