I have configured the ZHC5010 to send notifications for each key as described here: ZHC5010 configuration tutorial - #2 by andreasbrinch
I am experiencing erratic behavior. Sometimes it reacts instantly, sometimes several seconds goes by until a keypress is recognized. I am trying to debug the issue, have disabled all rules reacting to the key presses, and have noticed that when switching on a switch it seems to send a command to controller multiple times. From the log:
2018-03-27 22:12:05.128 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.135 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-03-27 22:12:05.140 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.144 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.148 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 60 0D 04 04 25 01 FF
2018-03-27 22:12:05.151 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2018-03-27 22:12:05.153 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2018-03-27 22:12:05.156 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@138ffd5 already registered
2018-03-27 22:12:05.159 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class MULTI_INSTANCE
2018-03-27 22:12:05.161 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received MULTI_INSTANCE command V2
2018-03-27 22:12:05.163 [INFO ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received a multi instance encapsulation with a destination endpoint = 4.
2018-03-27 22:12:05.167 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Requested Command Class = SWITCH_BINARY (0x25)
2018-03-27 22:12:05.169 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Endpoint = 4, calling handleApplicationCommandRequest.
2018-03-27 22:12:05.171 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 2
2018-03-27 22:12:05.174 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary SET
2018-03-27 22:12:05.176 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary report, value = 255
2018-03-27 22:12:05.178 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-03-27 22:12:05.180 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-03-27 22:12:05.183 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 4, command class = SWITCH_BINARY, value = 255
2018-03-27 22:12:05.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:controller:node2:switch_binary4 to ON [OnOffType]
2018-03-27 22:12:05.192 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=7, payload=02 03 8E 02 04
2018-03-27 22:12:05.196 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 60 0D 04 04 25 01 FF
2018-03-27 22:12:05.198 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=7, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2018-03-27 22:12:05.207 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-03-27 22:12:05.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-03-27 22:12:05.322 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.325 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-03-27 22:12:05.328 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.330 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.332 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 60 0D 04 04 25 01 FF
2018-03-27 22:12:05.333 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2018-03-27 22:12:05.334 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2018-03-27 22:12:05.336 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@138ffd5 already registered
2018-03-27 22:12:05.337 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class MULTI_INSTANCE
2018-03-27 22:12:05.339 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received MULTI_INSTANCE command V2
2018-03-27 22:12:05.340 [INFO ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received a multi instance encapsulation with a destination endpoint = 4.
2018-03-27 22:12:05.342 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Requested Command Class = SWITCH_BINARY (0x25)
2018-03-27 22:12:05.344 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Endpoint = 4, calling handleApplicationCommandRequest.
2018-03-27 22:12:05.345 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 2
2018-03-27 22:12:05.347 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary SET
2018-03-27 22:12:05.348 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary report, value = 255
2018-03-27 22:12:05.349 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-03-27 22:12:05.350 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-03-27 22:12:05.351 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 4, command class = SWITCH_BINARY, value = 255
2018-03-27 22:12:05.353 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:controller:node2:switch_binary4 to ON [OnOffType]
2018-03-27 22:12:05.356 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=7, payload=02 03 8E 02 04
2018-03-27 22:12:05.359 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 60 0D 04 04 25 01 FF
2018-03-27 22:12:05.360 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=7, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2018-03-27 22:12:05.362 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-03-27 22:12:05.363 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-03-27 22:12:05.483 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.486 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-03-27 22:12:05.487 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.489 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 02 07 60 0D 04 04 25 01 FF 45
2018-03-27 22:12:05.491 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 60 0D 04 04 25 01 FF
2018-03-27 22:12:05.492 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2018-03-27 22:12:05.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2018-03-27 22:12:05.494 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@138ffd5 already registered
2018-03-27 22:12:05.495 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class MULTI_INSTANCE
2018-03-27 22:12:05.496 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received MULTI_INSTANCE command V2
2018-03-27 22:12:05.497 [INFO ] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Received a multi instance encapsulation with a destination endpoint = 4.
2018-03-27 22:12:05.498 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Requested Command Class = SWITCH_BINARY (0x25)
2018-03-27 22:12:05.500 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Endpoint = 4, calling handleApplicationCommandRequest.
2018-03-27 22:12:05.501 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 2
2018-03-27 22:12:05.502 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary SET
2018-03-27 22:12:05.503 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary report, value = 255
2018-03-27 22:12:05.504 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-03-27 22:12:05.505 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-03-27 22:12:05.507 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 4, command class = SWITCH_BINARY, value = 255
2018-03-27 22:12:05.509 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:controller:node2:switch_binary4 to ON [OnOffType]
2018-03-27 22:12:05.511 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=7, payload=02 03 8E 02 04
2018-03-27 22:12:05.514 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 07 60 0D 04 04 25 01 FF
2018-03-27 22:12:05.515 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=7, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2018-03-27 22:12:05.517 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-03-27 22:12:05.518 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
From a few tries it seems that this does not happen when switching off a switch. Have anybody experienced similar behavior and is it just the way these devices work?
Thanks