Strange 5s delay after rule triggering and whole group responds. No errors in log

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,

Anyone?

@Kai Kreuzer, who do you think could have a look at this?
About 50% of the time I see the rule triggering at once, but it take 5s before anything happens to the z-wave devices in the group(s).

Best if you’d first analyze yourself, where the problem might be. Is it the rule engine? The Z-Wave binding? Try to figure out if it also occurs if you do NOT use Z-Wave on those items. This should give you a clue to answer those questions. Afterwards it will be much easier to (a) provide a description on how to reproduce it and (b) to tell who might be best to help on fixing it.

@OMR i have those delays also on my rules. Sometimes they have a delay with 1s and sometimes 20s :frowning:

I have these delays with different rules and bindings in it.

Kay

Thanks for chiming in @Kai

Is it the rule engine?

No, rule triggers immediately.

The Z-Wave binding?

Clearly, Z-wave binding receives group command immediately and translates it correctly into individual node messages, but they are not received by the nodes. My guess at this point is that they are delayed because of some protocol issue with the battery powered wall-switch (node22)

Try to figure out if it also occurs if you do NOT use Z-Wave on those items.

:slight_smile:

This should give you a clue to answer those questions.

Still left in the dark as to why the Z-wave binding delays those commands, and what is actually going on between these 2 log entries:

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!

@Kay_Pohl, my problem is with Z-wave group manipulations after rule triggering from a battery powered NodOn wall-switch. Same Z-wave group manipulations (ON/OFF) works immediately from a non-Z-wave Switch (GUI only).
What HW platform are you on?

@OMR I use RPI 2 with latest Openhabian.

OK, have you tried the most obvious: in a shell, monitor your java process CPU load with the ‘top’ command, just to verify it is not a performance issue there.

I’m on a Shuttle PC with a Dual Core Atom and have no other rule issues.

It’s just as it says - there’s a timeout, which means that the device did not respond to the message. The timeout is 5 seconds so this probably explains your 5 second delay. You need to look at why the device is not reliably communicating with the controller. Maybe it’s too far away, or maybe there’s some other problem…

Some other problem indeed.
Why shall the Z-wave binding talk to the switch just after receiving the command and block other node communication? The switch is 1,5m away from the Z-Stick, the other one with exactly the same problem is ~5m away, but only 1m from another beaming node.

If you send a command, it will try and send it to the switch :confused:. The ZWave controller can only handle a single outstanding transaction at once.

The only command I send is to the Z-wave group that the switch is not a part of:

rule "WallSwitchLivingRoom" 
when
        Item WallSwitchStua received update
then 
    var swState = WallSwitchStua.state 
	logInfo("RemoteNodon22", "Rule: Got: " + swState)
    
    switch swState {
	    case 1.0: {logInfo("RemoteNodon22", "Rule: Button1 SingleClick " + swState) sendCommand(lights, if (BuildInKjokkenBench.state==OFF) ON else OFF);
	    	                                                                        lights.state = if (BuildInKjokkenBench.state==OFF) ON else OFF
                                                                                    logInfo("RemoteNodon22", "lights.state=" + lights.state)
	    																		    All.state=lights.state 
	    																		    AllLR.state=lights.state	    
	    																		    AllK.state=lights.state	    
	    																		    AllDR.state=lights.state	    
	    																		   }	    
	    default:  {logInfo("RemoteNodon22", "Rule: Say what? " + swState)}
    }

end

Clearly this is translating into a command that is sent to the ZWave switch (Node 22) to change something. If this command doesn’t respond, then it will timeout after 5 seconds.

Maybe the real problem is that this device is part of a group - when you send an update to the group, it’s sending a command to a node that you don’t want it to send to? I’m not sure exactly what you’re doing, but all I can say is that you are sending a command to this node, and it is timing out - there’s no mystery in what the binding is doing at least :wink:

And I’m telling you that I do not intentionally send any commands to this node.
(Why would I want do send a command to a wall-switch aka remote? :slight_smile: )

My remotes are not part of the group I’m sending the command to:

Number WallSwitchStua             "Bryter (stua)"          <wallswitch>     (div, remotes)              { channel = "zwave:device:3f5c8071:node22:scene_number" }
Number WallSwitchKjokken          "Bryter (kjøkken)"       <wallswitch>     (div, remotes)              { channel = "zwave:device:3f5c8071:node6:scene_number" }

Ok, then this is another problem you need to resolve - I’m only talking about what the binding is doing. It’s clearly getting a command from somewhere. Maybe it’s not coming from the rule - I don’t know as you’ve only given a single line of the log so we’re really guessing a bit at the moment. I would suggest to look deeper into the log or at least provide more information.

:slight_smile: full debug log in my first post.

You can also use the log viewer to better understand whats happening -:
http://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

That’s unfortunately of little use as it’s pasted as a quote. Can you provide it without all the quote marks and formatting (use the </> button for formatting).

I will simply display this with the log viewer I mentioned earlier.

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,