When hitting the wall-switch (NODE 22) only one light in the group switches OFF. Rest follow 5s later.
OH2 Snapshot 2.1.0 #826
Search for ‘Rule’ receiving a 2.0 event from NODE 22.
At 23:29:36:320 there is a NODE 22 timeout re-queuing with 0 attempts left, but with no prior attempts. Communication with NODE 22 was what triggered the rule 5s earlier.
I fail to see in the log what is causing the timeout delay.
2017-03-08 23:29:31.281 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 16 05 5B 03 2D 00 02 94
2017-03-08 23:29:31.283 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:31.284 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 16 05 5B 03 2D 00 02 94
2017-03-08 23:29:31.284 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 16 05 5B 03 2D 00 02 94
2017-03-08 23:29:31.284 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 16 05 5B 03 2D 00 02
2017-03-08 23:29:31.285 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 22: Application Command Request (INITIALIZING:PING)
2017-03-08 23:29:31.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: Node is ALIVE. Init stage is PING.
2017-03-08 23:29:31.285 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2017-03-08 23:29:31.285 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node Status event during initialisation - Node is ALIVE
2017-03-08 23:29:31.285 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - PING: queue length(0), free to send(true)
2017-03-08 23:29:31.286 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: loop - PING try 1: stageAdvanced(false)
2017-03-08 23:29:31.286 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: PING - send NoOperation
2017-03-08 23:29:31.286 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 22: Creating new message for command No Operation
2017-03-08 23:29:31.286 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - queued packet. Queue length is 1
2017-03-08 23:29:31.286 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Putting message SendData in wakeup queue.
2017-03-08 23:29:31.287 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2017-03-08 23:29:31.287 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Setting ONLINE
2017-03-08 23:29:31.288 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 22: Node Status event - Node is ALIVE
2017-03-08 23:29:31.288 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 22: Incoming command class CENTRAL_SCENE
2017-03-08 23:29:31.288 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 22: Received CENTRAL_SCENE command V2
2017-03-08 23:29:31.288 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 22: Received scene 2 at key 0 [Single Press]
2017-03-08 23:29:31.288 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-03-08 23:29:31.288 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: CC event during initialisation stage IDLE
2017-03-08 23:29:31.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-03-08 23:29:31.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got a value event from Z-Wave network, endpoint = 0, command class = CENTRAL_SCENE, value = 2.0
2017-03-08 23:29:31.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Updating channel state zwave:device:3f5c8071:node22:scene_number to 2.0 [DecimalType]
2017-03-08 23:29:31.290 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Transaction not completed: node address inconsistent. lastSent=7, incoming=255
2017-03-08 23:29:31.304 [INFO ] [smarthome.model.script.RemoteNodon22] - Rule: Got: 2.0
2017-03-08 23:29:31.305 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 16 02 84 07 64
2017-03-08 23:29:31.306 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:31.306 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 16 02 84 07 64
2017-03-08 23:29:31.307 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 16 02 84 07 64
2017-03-08 23:29:31.307 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 16 02 84 07
2017-03-08 23:29:31.307 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 22: Application Command Request (ALIVE:DETAILS)
2017-03-08 23:29:31.308 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 22: Incoming command class WAKE_UP
2017-03-08 23:29:31.308 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Received Wake Up Request
2017-03-08 23:29:31.308 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Received WAKE_UP_NOTIFICATION
2017-03-08 23:29:31.308 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Is awake with 1 messages in the wake-up queue.
2017-03-08 23:29:31.309 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2017-03-08 23:29:31.309 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Wakeup during initialisation.
2017-03-08 23:29:31.309 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - DETAILS: queue length(1), free to send(false)
2017-03-08 23:29:31.309 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - queued packet. Queue length is 1
2017-03-08 23:29:31.309 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-03-08 23:29:31.309 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-03-08 23:29:31.310 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveWakeUpEvent
2017-03-08 23:29:31.319 [INFO ] [smarthome.model.script.RemoteNodon22] - Rule: Button2 SingleClick 2.0
2017-03-08 23:29:31.319 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 16 01 00 25 9D 4B
2017-03-08 23:29:31.319 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-03-08 23:29:31.319 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 22: Sending REQUEST Message = 01 08 00 13 16 01 00 25 9D 4B
2017-03-08 23:29:31.319 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Transaction not completed: node address inconsistent. lastSent=7, incoming=255
2017-03-08 23:29:31.332 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:31.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:3f5c8071:node13:switch_dimmer --> OFF
2017-03-08 23:29:31.335 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 13: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.335 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-03-08 23:29:31.386 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9D 00 00 02 74
2017-03-08 23:29:31.387 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:31.387 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:31.387 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:31.388 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:31.388 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 22: Sent Data successfully placed on stack.
2017-03-08 23:29:31.394 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:31.395 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9D 00 00 02 00 00 7A
2017-03-08 23:29:31.395 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 9D 00 00 02 00 00 7A
2017-03-08 23:29:31.396 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9D 00 00 02
2017-03-08 23:29:31.396 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 22: SendData Request. CallBack ID = 157, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:31.396 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 22: Already processed another send data request for this callback Id, ignoring.
2017-03-08 23:29:31.405 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:3f5c8071:node10:switch_dimmer --> OFF
2017-03-08 23:29:31.405 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.406 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-03-08 23:29:31.409 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:3f5c8071:node8:switch_dimmer --> OFF
2017-03-08 23:29:31.410 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 8: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.410 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-03-08 23:29:31.417 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:3f5c8071:node9:switch_dimmer --> OFF
2017-03-08 23:29:31.418 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 9: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.418 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2017-03-08 23:29:31.424 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Command received zwave:device:3f5c8071:node19:switch_dimmer --> OFF
2017-03-08 23:29:31.425 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 19: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.425 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 6. Queue={}
2017-03-08 23:29:31.440 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Command received zwave:device:3f5c8071:node18:switch_dimmer --> OFF
2017-03-08 23:29:31.441 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.441 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 7. Queue={}
2017-03-08 23:29:31.451 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Command received zwave:device:3f5c8071:node14:switch_dimmer --> OFF
2017-03-08 23:29:31.452 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 14: Creating new message for command SWITCH_MULTILEVEL_SET
2017-03-08 23:29:31.452 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 8. Queue={}
2017-03-08 23:29:36.320 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 22: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-08 23:29:36.321 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Is sleeping
2017-03-08 23:29:36.321 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Putting message SendData in wakeup queue.
2017-03-08 23:29:36.321 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 7
2017-03-08 23:29:36.321 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Message already on the wake-up queue. Removing original.
2017-03-08 23:29:36.321 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 22: Putting message SendData in wakeup queue.
2017-03-08 23:29:36.322 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 6
2017-03-08 23:29:36.322 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0D 03 26 01 00 25 9F 75
2017-03-08 23:29:36.322 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0A 00 13 0D 03 26 01 00 25 9F 75
2017-03-08 23:29:36.332 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.333 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.333 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:36.334 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.334 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:36.334 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: Sent Data successfully placed on stack.
2017-03-08 23:29:36.352 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9F 00 00 03 77
2017-03-08 23:29:36.353 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.353 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9F 00 00 03 00 00 79
2017-03-08 23:29:36.354 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 9F 00 00 03 00 00 79
2017-03-08 23:29:36.354 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9F 00 00 03
2017-03-08 23:29:36.354 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: SendData Request. CallBack ID = 159, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:36.354 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Starting initialisation from DONE
2017-03-08 23:29:36.355 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@f212f0d already registered
2017-03-08 23:29:36.355 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=13, callback=159, payload=0D 03 26 01 00
2017-03-08 23:29:36.355 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9F 00 00 03
2017-03-08 23:29:36.355 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=159, expected=SendData, cancelled=false transaction complete!
2017-03-08 23:29:36.355 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.356 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.356 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Response processed after 32ms/4172ms.
2017-03-08 23:29:36.356 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 5
2017-03-08 23:29:36.356 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 26 01 00 25 A0 4D
2017-03-08 23:29:36.357 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 26 01 00 25 A0 4D
2017-03-08 23:29:36.366 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.367 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.367 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:36.368 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.368 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:36.368 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: Sent Data successfully placed on stack.
2017-03-08 23:29:36.521 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A0 00 00 10 5B
2017-03-08 23:29:36.522 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.522 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A0 00 00 10 00 00 55
2017-03-08 23:29:36.523 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A0 00 00 10 00 00 55
2017-03-08 23:29:36.523 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A0 00 00 10
2017-03-08 23:29:36.523 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 160, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:36.523 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Starting initialisation from DONE
2017-03-08 23:29:36.523 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@53b64e7f already registered
2017-03-08 23:29:36.524 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=10, callback=160, payload=0A 03 26 01 00
2017-03-08 23:29:36.524 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A0 00 00 10
2017-03-08 23:29:36.524 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=160, expected=SendData, cancelled=false transaction complete!
2017-03-08 23:29:36.524 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.524 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.525 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 10: Response processed after 167ms/4172ms.
2017-03-08 23:29:36.525 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2017-03-08 23:29:36.525 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 08 03 26 01 00 25 A1 4E
2017-03-08 23:29:36.526 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 26 01 00 25 A1 4E
2017-03-08 23:29:36.535 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.536 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.536 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:36.537 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.537 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:36.537 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: Sent Data successfully placed on stack.
2017-03-08 23:29:36.555 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A1 00 00 03 49
2017-03-08 23:29:36.556 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.556 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A1 00 00 03 00 00 47
2017-03-08 23:29:36.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A1 00 00 03 00 00 47
2017-03-08 23:29:36.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A1 00 00 03
2017-03-08 23:29:36.557 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: SendData Request. CallBack ID = 161, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:36.557 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Starting initialisation from DONE
2017-03-08 23:29:36.558 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@3e9450ce already registered
2017-03-08 23:29:36.558 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=8, callback=161, payload=08 03 26 01 00
2017-03-08 23:29:36.558 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A1 00 00 03
2017-03-08 23:29:36.558 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=161, expected=SendData, cancelled=false transaction complete!
2017-03-08 23:29:36.558 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.559 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.559 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 8: Response processed after 32ms/4172ms.
2017-03-08 23:29:36.559 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2017-03-08 23:29:36.559 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 09 03 26 01 00 25 A2 4C
2017-03-08 23:29:36.560 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 9: Sending REQUEST Message = 01 0A 00 13 09 03 26 01 00 25 A2 4C
2017-03-08 23:29:36.569 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.570 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.570 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:36.571 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.571 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:36.571 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: Sent Data successfully placed on stack.
2017-03-08 23:29:36.589 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A2 00 00 02 4B
2017-03-08 23:29:36.590 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.590 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A2 00 00 02 00 00 45
2017-03-08 23:29:36.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A2 00 00 02 00 00 45
2017-03-08 23:29:36.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A2 00 00 02
2017-03-08 23:29:36.591 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 162, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:36.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE
2017-03-08 23:29:36.592 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@73a15c1a already registered
2017-03-08 23:29:36.592 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=9, callback=162, payload=09 03 26 01 00
2017-03-08 23:29:36.592 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A2 00 00 02
2017-03-08 23:29:36.592 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=162, expected=SendData, cancelled=false transaction complete!
2017-03-08 23:29:36.592 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.593 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.593 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Response processed after 32ms/4172ms.
2017-03-08 23:29:36.593 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-03-08 23:29:36.593 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 13 03 26 01 00 25 A3 57
2017-03-08 23:29:36.594 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 26 01 00 25 A3 57
2017-03-08 23:29:36.603 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.604 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.604 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:36.605 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.605 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:36.605 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 19: Sent Data successfully placed on stack.
2017-03-08 23:29:36.619 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A3 00 00 02 4A
2017-03-08 23:29:36.620 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.620 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A3 00 00 02 00 00 44
2017-03-08 23:29:36.621 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A3 00 00 02 00 00 44
2017-03-08 23:29:36.621 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A3 00 00 02
2017-03-08 23:29:36.621 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 163, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:36.621 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Starting initialisation from DONE
2017-03-08 23:29:36.622 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@405e1c18 already registered
2017-03-08 23:29:36.622 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=19, callback=163, payload=13 03 26 01 00
2017-03-08 23:29:36.622 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A3 00 00 02
2017-03-08 23:29:36.622 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=163, expected=SendData, cancelled=false transaction complete!
2017-03-08 23:29:36.622 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.623 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-03-08 23:29:36.623 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 19: Response processed after 28ms/4172ms.
2017-03-08 23:29:36.623 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-03-08 23:29:36.623 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 12 03 26 01 00 25 A4 51
2017-03-08 23:29:36.624 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 0A 00 13 12 03 26 01 00 25 A4 51
2017-03-08 23:29:36.632 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.633 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.633 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-03-08 23:29:36.634 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-03-08 23:29:36.634 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-08 23:29:36.634 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: Sent Data successfully placed on stack.
2017-03-08 23:29:36.653 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A4 00 00 03 4C
2017-03-08 23:29:36.654 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-08 23:29:36.654 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A4 00 00 03 00 00 42
2017-03-08 23:29:36.655 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A4 00 00 03 00 00 42
2017-03-08 23:29:36.655 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A4 00 00 03
2017-03-08 23:29:36.655 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 164, Status = Transmission complete and ACK received(0)
2017-03-08 23:29:36.655 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Starting initialisation from DONE
2017-03-08 23:29:36.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@34df8540 already registered
2017-03-08 23:29:36.656 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set,