2020-05-19 08:11:03.561 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:03.562 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:05 CDT 2020 - 1998ms 2020-05-19 08:11:03.562 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:03.564 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 103: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:03.564 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-05-19 08:11:03.565 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:03.566 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 2020-05-19 08:11:03.566 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:05 CDT 2020 - 1994ms 2020-05-19 08:11:03.567 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24 2020-05-19 08:11:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:03.569 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:03.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 103: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:03.571 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:03.572 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:03.572 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:03.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:03.574 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:03.575 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:03.577 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:03.579 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:05 CDT 2020 - 1981ms 2020-05-19 08:11:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 103: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:03.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 103: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:03.586 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:03.588 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:03.589 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response 2020-05-19 08:11:03.591 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: sentData successfully placed on stack. 2020-05-19 08:11:03.592 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:03.593 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:03.594 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:03.596 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance TO: WAIT_REQUEST 2020-05-19 08:11:03.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 103: Advanced to WAIT_REQUEST 2020-05-19 08:11:03.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 103: Transaction not completed 2020-05-19 08:11:03.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:03.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:03.603 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:03.604 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:03.606 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:08 CDT 2020 - 4994ms 2020-05-19 08:11:04.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@ffdca 2020-05-19 08:11:04.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Bump transaction 106 priority from Controller to Immediate 2020-05-19 08:11:04.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Adding to device queue 2020-05-19 08:11:04.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Added 106 to queue - size 17 2020-05-19 08:11:04.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:04.139 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:04.142 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:04.146 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:08 CDT 2020 - 4454ms 2020-05-19 08:11:04.649 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: listening == false, frequentlyListening == false, awake == true 2020-05-19 08:11:04.651 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF 2020-05-19 08:11:04.654 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: No more messages, go back to sleep 2020-05-19 08:11:04.656 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 25: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION 2020-05-19 08:11:04.658 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Encapsulating message, endpoint 0 2020-05-19 08:11:04.659 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported 2020-05-19 08:11:04.661 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured 2020-05-19 08:11:04.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@9ab6a8 2020-05-19 08:11:04.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Bump transaction 107 priority from Immediate to Immediate 2020-05-19 08:11:04.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Adding to device queue 2020-05-19 08:11:04.670 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Added 107 to queue - size 18 2020-05-19 08:11:04.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:04.673 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:04.675 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:04.678 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:08 CDT 2020 - 3922ms 2020-05-19 08:11:08.599 [TRACE] [sactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions 2020-05-19 08:11:08.601 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 13: TID 103: Timeout at state WAIT_REQUEST. 1 retries remaining. 2020-05-19 08:11:08.603 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2020-05-19 08:11:08.604 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 103: Transaction ABORTED 2020-05-19 08:11:08.606 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = SendDataAbort (0x16), type = Request 2020-05-19 08:11:08.608 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -22 2020-05-19 08:11:08.610 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2020-05-19 08:11:08.612 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2020-05-19 08:11:08.615 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:08.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:08.617 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:08.618 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:08.619 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:08.620 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:08.620 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:08.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:08.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 103: [ABORTED] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:08.624 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:20 CDT 2020 - 11982ms 2020-05-19 08:11:08.626 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:08.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:08.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:08.632 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:08.633 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:08.635 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:20 CDT 2020 - 11971ms 2020-05-19 08:11:10.742 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:10.745 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 47 01 02 CF 60 2020-05-19 08:11:10.749 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 47 01 02 CF 60 2020-05-19 08:11:10.751 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 96 2020-05-19 08:11:10.753 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:10.756 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 1: Message payload = 47 01 02 CF 2020-05-19 08:11:10.758 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:10.760 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:10.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=71, payload=47 01 02 CF 2020-05-19 08:11:10.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=71, payload=47 01 02 CF 2020-05-19 08:11:10.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 103: [ABORTED] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:10.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:10.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 103: [ABORTED] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:10.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 103: (Callback 71) 2020-05-19 08:11:10.771 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-05-19 08:11:10.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 103: callback 71 2020-05-19 08:11:10.773 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=71, payload=47 01 02 CF 2020-05-19 08:11:10.774 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:10.776 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request 2020-05-19 08:11:10.777 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: SendData Request. CallBack ID = 71, Status = Transmission complete, no ACK received(1) 2020-05-19 08:11:10.778 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 103: Transaction CANCELLED 2020-05-19 08:11:10.779 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance ST: CANCELLED 2020-05-19 08:11:10.780 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:10.782 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=1, callback=71, payload=47 01 02 CF 2020-05-19 08:11:10.783 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 103: TransactionAdvance TO: CANCELLED 2020-05-19 08:11:10.784 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:10.785 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:10.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Retry count exceeded. Discarding message: TID 103: [CANCELLED] priority=Immediate, requiresResponse=true, callback: 71 2020-05-19 08:11:10.788 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: listening == false, frequentlyListening == true, awake == false 2020-05-19 08:11:10.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 103: Transaction completed 2020-05-19 08:11:10.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:103 CANCELLED 2020-05-19 08:11:10.792 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:10.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 103: Transaction event listener: DONE: CANCELLED -> 2020-05-19 08:11:10.794 [TRACE] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 103 -- 2020-05-19 08:11:10.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:10.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:10.800 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@90f7ce 2020-05-19 08:11:10.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:10.801 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node Init transaction completed with response COMPLETE 2020-05-19 08:11:10.802 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:10.802 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Encapsulating message, endpoint 1 2020-05-19 08:11:10.804 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Encapsulating message, instance / endpoint 1 2020-05-19 08:11:10.804 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 27: Node not awake! 2020-05-19 08:11:10.805 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 13: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-05-19 08:11:10.805 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:10.806 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 22: Node not awake! 2020-05-19 08:11:10.806 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: SECURITY not supported 2020-05-19 08:11:10.807 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:10.808 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake! 2020-05-19 08:11:10.808 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-05-19 08:11:10.809 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: listening == false, frequentlyListening == true, awake == false 2020-05-19 08:11:10.810 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: ZWaveCommandClassTransactionPayload - send to node 2020-05-19 08:11:10.811 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2020-05-19 08:11:10.812 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Transaction requires security 2020-05-19 08:11:10.813 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Encapsulating message, endpoint 0 2020-05-19 08:11:11.475 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 24: isNonceAvailable = null 2020-05-19 08:11:11.477 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_GET version 1 2020-05-19 08:11:11.477 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: SECURITY not supported 2020-05-19 08:11:11.479 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 24: Creating empty message of class = SendData (0x13), type = Request 2020-05-19 08:11:11.481 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-05-19 08:11:11.481 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 74 2020-05-19 08:11:11.484 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 18 02 98 40 25 48 4A 2020-05-19 08:11:11.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@b3d1f2 2020-05-19 08:11:11.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Bump transaction 109 priority from Get to Immediate 2020-05-19 08:11:11.487 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 09 00 13 18 02 98 40 25 48 4A 2020-05-19 08:11:11.492 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:11.494 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: Transaction Start type SendData 2020-05-19 08:11:11.494 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:11.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 108: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:11.496 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:11.498 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SECURITY 2020-05-19 08:11:11.500 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 128 2020-05-19 08:11:11.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:11.501 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2020-05-19 08:11:11.503 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:11.503 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:11.505 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:13 CDT 2020 - 1998ms 2020-05-19 08:11:11.508 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-05-19 08:11:11.507 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 108: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:11.511 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 2020-05-19 08:11:11.512 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24 2020-05-19 08:11:11.514 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:11.516 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:11.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue 2020-05-19 08:11:11.518 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:11.520 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:11.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 109 to queue - size 18 2020-05-19 08:11:11.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:11.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:11.523 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:11.525 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:11.527 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:13 CDT 2020 - 1976ms 2020-05-19 08:11:11.529 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:11.532 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:13 CDT 2020 - 1971ms 2020-05-19 08:11:11.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:11.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 108: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:11.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:11.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:11.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 108: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:11.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:11.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 108: [WAIT_RESPONSE] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:11.546 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:11.547 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:11.549 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response 2020-05-19 08:11:11.551 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack. 2020-05-19 08:11:11.553 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:11.554 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:11.556 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:11.558 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance TO: WAIT_REQUEST 2020-05-19 08:11:11.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 108: Advanced to WAIT_REQUEST 2020-05-19 08:11:11.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 108: Transaction not completed 2020-05-19 08:11:11.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:11.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:11.566 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:11.567 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:11.569 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:16 CDT 2020 - 4992ms 2020-05-19 08:11:12.872 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:12.877 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 48 00 00 8A 29 2020-05-19 08:11:12.880 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 48 00 00 8A 29 2020-05-19 08:11:12.882 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 41 2020-05-19 08:11:12.884 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:12.886 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 48 00 00 8A 2020-05-19 08:11:12.889 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:12.891 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:12.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 8A 2020-05-19 08:11:12.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 8A 2020-05-19 08:11:12.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 108: [WAIT_REQUEST] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:12.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:12.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 108: [WAIT_REQUEST] priority=High, requiresResponse=true, callback: 72 2020-05-19 08:11:12.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 108: (Callback 72) 2020-05-19 08:11:12.904 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-05-19 08:11:12.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 108: callback 72 2020-05-19 08:11:12.908 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 8A 2020-05-19 08:11:12.910 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:12.912 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request 2020-05-19 08:11:12.914 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 72, Status = Transmission complete and ACK received(0) 2020-05-19 08:11:12.916 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance ST: WAIT_REQUEST 2020-05-19 08:11:12.918 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:12.920 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=72, payload=48 00 00 8A 2020-05-19 08:11:12.922 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler 2020-05-19 08:11:12.924 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance TO: WAIT_DATA 2020-05-19 08:11:12.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 108: Advanced to WAIT_DATA 2020-05-19 08:11:12.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 108: Transaction not completed 2020-05-19 08:11:12.929 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:12.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:12.932 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing 2020-05-19 08:11:12.934 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:12.936 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:17 CDT 2020 - 4992ms 2020-05-19 08:11:12.959 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:12.964 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 18 0A 98 80 E7 2B 6F 65 34 9A F3 C5 BF 2020-05-19 08:11:12.968 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 00 04 00 18 0A 98 80 E7 2B 6F 65 34 9A F3 C5 BF 2020-05-19 08:11:12.970 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -65 2020-05-19 08:11:12.972 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:12.975 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 24: Message payload = 00 18 0A 98 80 E7 2B 6F 65 34 9A F3 C5 2020-05-19 08:11:12.976 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:12.978 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:12.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 0A 98 80 E7 2B 6F 65 34 9A F3 C5 2020-05-19 08:11:12.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 0A 98 80 E7 2B 6F 65 34 9A F3 C5 2020-05-19 08:11:12.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-05-19 08:11:12.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Application Command Request (ALIVE:DYNAMIC_VALUES) 2020-05-19 08:11:12.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0 2020-05-19 08:11:12.991 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY check internal 2020-05-19 08:11:12.992 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 24: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_REPORT 2020-05-19 08:11:12.997 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 24: NONCE Received start... 2020-05-19 08:11:12.999 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 24: NONCE Received start null 2020-05-19 08:11:13.002 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 24: NONCE Received ZWaveNonce [nonceBytes=(E7 2B 6F 65 34 9A F3 C5 ), timer=777914, valid=true] 2020-05-19 08:11:13.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Commands processed 1. 2020-05-19 08:11:13.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a2fc34. 2020-05-19 08:11:13.007 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction 108 ApplicationCommandHandler. 2020-05-19 08:11:13.008 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : state >> WAIT_DATA 2020-05-19 08:11:13.010 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : node >> 24 2020-05-19 08:11:13.011 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : class >> 152 == 152. 2020-05-19 08:11:13.013 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : commd >> 128 == 128. 2020-05-19 08:11:13.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a2fc34. 2020-05-19 08:11:13.016 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance ST: WAIT_DATA 2020-05-19 08:11:13.017 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:13.020 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance RX: Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 0A 98 80 E7 2B 6F 65 34 9A F3 C5 2020-05-19 08:11:13.021 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 108: TransactionAdvance TO: DONE 2020-05-19 08:11:13.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:108 DONE 2020-05-19 08:11:13.024 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:13.030 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:13.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-05-19 08:11:13.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2020-05-19 08:11:13.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:13.034 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue 2020-05-19 08:11:13.036 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Transaction requires security 2020-05-19 08:11:13.037 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: NONCE available so encap and send. 2020-05-19 08:11:13.038 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_MESSAGE_ENCAPSULATION version 1 2020-05-19 08:11:13.040 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 24: SECURITY_TXD 63 02 10 2020-05-19 08:11:13.041 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 24: Creating empty message of class = SendData (0x13), type = Request 2020-05-19 08:11:13.042 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 102 2020-05-19 08:11:13.044 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1E 00 13 18 17 98 81 D9 DA E9 31 F2 5D 07 B1 29 D4 24 DF E7 6F 96 D2 E0 C1 FE 7E 47 25 49 66 2020-05-19 08:11:13.046 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 1E 00 13 18 17 98 81 D9 DA E9 31 F2 5D 07 B1 29 D4 24 DF E7 6F 96 D2 E0 C1 FE 7E 47 25 49 66 2020-05-19 08:11:13.047 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:13.048 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: Transaction Start type SendData 2020-05-19 08:11:13.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 105: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.050 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_USER_CODE 2020-05-19 08:11:13.051 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:13.051 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3 2020-05-19 08:11:13.052 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2020-05-19 08:11:13.052 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:13.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:13.054 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.055 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:15 CDT 2020 - 1998ms 2020-05-19 08:11:13.056 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 105: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.057 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:13.057 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.059 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:15 CDT 2020 - 1994ms 2020-05-19 08:11:13.059 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-05-19 08:11:13.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:13.060 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 2020-05-19 08:11:13.061 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24 2020-05-19 08:11:13.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 105: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.062 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:13.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:13.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.064 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:13.065 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:13.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:13.066 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:13.066 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:13.067 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.069 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:15 CDT 2020 - 1985ms 2020-05-19 08:11:13.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.070 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 105: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:13.073 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 105: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.075 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:13.077 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response 2020-05-19 08:11:13.078 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack. 2020-05-19 08:11:13.079 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:13.080 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:13.081 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.082 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance TO: WAIT_REQUEST 2020-05-19 08:11:13.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 105: Advanced to WAIT_REQUEST 2020-05-19 08:11:13.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 105: Transaction not completed 2020-05-19 08:11:13.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.086 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:13.087 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:13.088 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.089 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:18 CDT 2020 - 4995ms 2020-05-19 08:11:13.155 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:13.158 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 49 00 00 0B A9 2020-05-19 08:11:13.159 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 49 00 00 0B A9 2020-05-19 08:11:13.161 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -87 2020-05-19 08:11:13.162 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:13.163 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 49 00 00 0B 2020-05-19 08:11:13.164 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:13.166 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:13.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 0B 2020-05-19 08:11:13.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 0B 2020-05-19 08:11:13.170 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 105: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:13.172 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 105: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 73 2020-05-19 08:11:13.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 105: (Callback 73) 2020-05-19 08:11:13.174 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-05-19 08:11:13.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 105: callback 73 2020-05-19 08:11:13.177 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 0B 2020-05-19 08:11:13.178 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:13.179 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request 2020-05-19 08:11:13.180 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 73, Status = Transmission complete and ACK received(0) 2020-05-19 08:11:13.181 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance ST: WAIT_REQUEST 2020-05-19 08:11:13.182 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:13.183 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=73, payload=49 00 00 0B 2020-05-19 08:11:13.184 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler 2020-05-19 08:11:13.185 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance TO: WAIT_DATA 2020-05-19 08:11:13.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 105: Advanced to WAIT_DATA 2020-05-19 08:11:13.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 105: Transaction not completed 2020-05-19 08:11:13.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:13.190 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing 2020-05-19 08:11:13.191 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.192 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:18 CDT 2020 - 4995ms 2020-05-19 08:11:13.697 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:13.699 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 18 02 98 40 31 2020-05-19 08:11:13.701 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 04 00 18 02 98 40 31 2020-05-19 08:11:13.702 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 49 2020-05-19 08:11:13.703 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:13.705 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 24: Message payload = 00 18 02 98 40 2020-05-19 08:11:13.706 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:13.708 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:13.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 02 98 40 2020-05-19 08:11:13.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 02 98 40 2020-05-19 08:11:13.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-05-19 08:11:13.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Application Command Request (ALIVE:DYNAMIC_VALUES) 2020-05-19 08:11:13.714 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0 2020-05-19 08:11:13.715 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY check internal 2020-05-19 08:11:13.716 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 24: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET 2020-05-19 08:11:13.719 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1 2020-05-19 08:11:13.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added to secure queue - size 1 2020-05-19 08:11:13.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Commands processed 1. 2020-05-19 08:11:13.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@41daea. 2020-05-19 08:11:13.724 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction 105 ApplicationCommandHandler. 2020-05-19 08:11:13.725 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : state >> WAIT_DATA 2020-05-19 08:11:13.726 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : node >> 24 2020-05-19 08:11:13.727 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : class >> 152 == 99. 2020-05-19 08:11:13.729 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : commd >> 64 == 3. 2020-05-19 08:11:13.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@41daea. 2020-05-19 08:11:13.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-05-19 08:11:13.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-05-19 08:11:13.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:13.738 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue 2020-05-19 08:11:13.739 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2020-05-19 08:11:13.741 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 24: Creating empty message of class = SendData (0x13), type = Request 2020-05-19 08:11:13.743 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 100 2020-05-19 08:11:13.745 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 18 0A 98 80 BD AD F2 C0 0E 5C C5 49 25 4A 64 2020-05-19 08:11:13.748 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 11 00 13 18 0A 98 80 BD AD F2 C0 0E 5C C5 49 25 4A 64 2020-05-19 08:11:13.750 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:13.752 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: Transaction Start type SendData 2020-05-19 08:11:13.753 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:13.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 110: [WAIT_RESPONSE] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.755 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:13.755 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2020-05-19 08:11:13.757 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0 2020-05-19 08:11:13.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:13.758 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 2 2020-05-19 08:11:13.759 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:13.760 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.762 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-05-19 08:11:13.762 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:15 CDT 2020 - 1998ms 2020-05-19 08:11:13.763 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 110: [WAIT_RESPONSE] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.764 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 2020-05-19 08:11:13.765 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.766 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24 2020-05-19 08:11:13.767 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:15 CDT 2020 - 1993ms 2020-05-19 08:11:13.768 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:13.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:13.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 110: [WAIT_RESPONSE] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.770 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:13.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:13.772 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:13.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.774 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:13.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 2 out at start. Holdoff false. 2020-05-19 08:11:13.776 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:13.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.778 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.780 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:15 CDT 2020 - 1980ms 2020-05-19 08:11:13.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 110: [WAIT_RESPONSE] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 2 2020-05-19 08:11:13.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 110: [WAIT_RESPONSE] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.788 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.790 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:13.791 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response 2020-05-19 08:11:13.793 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack. 2020-05-19 08:11:13.795 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:13.796 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance WT: null {} 2020-05-19 08:11:13.798 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:13.800 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance TO: WAIT_REQUEST 2020-05-19 08:11:13.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 110: Advanced to WAIT_REQUEST 2020-05-19 08:11:13.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 110: Transaction not completed 2020-05-19 08:11:13.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 2 out at start. Holdoff false. 2020-05-19 08:11:13.807 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:13.809 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.811 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:18 CDT 2020 - 4376ms 2020-05-19 08:11:13.832 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:13.835 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4A 00 00 08 A9 2020-05-19 08:11:13.836 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 4A 00 00 08 A9 2020-05-19 08:11:13.838 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -87 2020-05-19 08:11:13.839 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:13.841 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 4A 00 00 08 2020-05-19 08:11:13.843 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:13.848 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:13.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=74, payload=4A 00 00 08 2020-05-19 08:11:13.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=74, payload=4A 00 00 08 2020-05-19 08:11:13.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 110: [WAIT_REQUEST] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 2 2020-05-19 08:11:13.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 110: [WAIT_REQUEST] priority=NonceResponse, requiresResponse=true, callback: 74 2020-05-19 08:11:13.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 105: (Callback 73) 2020-05-19 08:11:13.856 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - NO callback match! (73 <> 74) 2020-05-19 08:11:13.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 110: (Callback 74) 2020-05-19 08:11:13.858 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-05-19 08:11:13.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 110: callback 74 2020-05-19 08:11:13.860 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=74, payload=4A 00 00 08 2020-05-19 08:11:13.861 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:13.862 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request 2020-05-19 08:11:13.863 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 74, Status = Transmission complete and ACK received(0) 2020-05-19 08:11:13.865 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 110: Transaction COMPLETED 2020-05-19 08:11:13.866 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance ST: DONE 2020-05-19 08:11:13.867 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance WT: null {} 2020-05-19 08:11:13.868 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=74, payload=4A 00 00 08 2020-05-19 08:11:13.869 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 110: TransactionAdvance TO: DONE 2020-05-19 08:11:13.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Response processed after 118ms 2020-05-19 08:11:13.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 110: Transaction completed 2020-05-19 08:11:13.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:110 DONE 2020-05-19 08:11:13.873 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:13.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:13.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:13.885 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:13.886 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing 2020-05-19 08:11:13.887 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:13.888 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:18 CDT 2020 - 4299ms 2020-05-19 08:11:13.925 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:13.929 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 04 00 18 18 98 81 F4 F7 4E 48 90 B0 C3 E7 3E F3 E4 80 B5 BD 14 D8 E0 B8 AE 0F 6D 69 6D 2020-05-19 08:11:13.931 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 1E 00 04 00 18 18 98 81 F4 F7 4E 48 90 B0 C3 E7 3E F3 E4 80 B5 BD 14 D8 E0 B8 AE 0F 6D 69 6D 2020-05-19 08:11:13.933 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 109 2020-05-19 08:11:13.934 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:13.937 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 24: Message payload = 00 18 18 98 81 F4 F7 4E 48 90 B0 C3 E7 3E F3 E4 80 B5 BD 14 D8 E0 B8 AE 0F 6D 69 2020-05-19 08:11:13.938 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:13.940 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:13.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 18 98 81 F4 F7 4E 48 90 B0 C3 E7 3E F3 E4 80 B5 BD 14 D8 E0 B8 AE 0F 6D 69 2020-05-19 08:11:13.945 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 18 98 81 F4 F7 4E 48 90 B0 C3 E7 3E F3 E4 80 B5 BD 14 D8 E0 B8 AE 0F 6D 69 2020-05-19 08:11:13.946 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-05-19 08:11:13.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Application Command Request (ALIVE:DYNAMIC_VALUES) 2020-05-19 08:11:13.948 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Decapsulating COMMAND_CLASS_SECURITY 2020-05-19 08:11:13.951 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 24: SECURITY_RXD 63 03 10 00 2020-05-19 08:11:13.952 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Incoming command class COMMAND_CLASS_USER_CODE, endpoint 0 2020-05-19 08:11:13.953 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 24: Received COMMAND_CLASS_USER_CODE V1 USER_CODE_REPORT 2020-05-19 08:11:13.956 [DEBUG] [mmandclass.ZWaveUserCodeCommandClass] - NODE 24: USER_CODE_REPORT 16 is AVAILABLE 2020-05-19 08:11:13.957 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveUserCodeValueEvent 2020-05-19 08:11:13.958 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveUserCodeValueEvent 2020-05-19 08:11:13.959 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_USER_CODE, value= 2020-05-19 08:11:13.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Config updated 2020-05-19 08:11:13.995 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Checking channel=zwave:device:c9fd3b4d:node24:lock_door, cmdClass=COMMAND_CLASS_DOOR_LOCK, endpoint=0 2020-05-19 08:11:13.996 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Checking channel=zwave:device:c9fd3b4d:node24:alarm_access, cmdClass=COMMAND_CLASS_ALARM, endpoint=0 2020-05-19 08:11:13.998 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Checking channel=zwave:device:c9fd3b4d:node24:alarm_power, cmdClass=COMMAND_CLASS_ALARM, endpoint=0 2020-05-19 08:11:13.999 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Checking channel=zwave:device:c9fd3b4d:node24:alarm_raw, cmdClass=COMMAND_CLASS_ALARM, endpoint=0 2020-05-19 08:11:14.000 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Checking channel=zwave:device:c9fd3b4d:node24:battery-level, cmdClass=COMMAND_CLASS_BATTERY, endpoint=0 2020-05-19 08:11:14.001 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Checking channel=zwave:device:c9fd3b4d:node24:time_offset, cmdClass=COMMAND_CLASS_TIME_PARAMETERS, endpoint=0 2020-05-19 08:11:14.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Commands processed 1. 2020-05-19 08:11:14.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1d86f54. 2020-05-19 08:11:14.004 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction 105 ApplicationCommandHandler. 2020-05-19 08:11:14.005 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : state >> WAIT_DATA 2020-05-19 08:11:14.006 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : node >> 24 2020-05-19 08:11:14.008 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : class >> 99 == 99. 2020-05-19 08:11:14.009 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking transaction : commd >> 3 == 3. 2020-05-19 08:11:14.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1d86f54. 2020-05-19 08:11:14.011 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance ST: WAIT_DATA 2020-05-19 08:11:14.012 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance WT: ApplicationCommandHandler {} 2020-05-19 08:11:14.015 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance RX: Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 18 98 81 F4 F7 4E 48 90 B0 C3 E7 3E F3 E4 80 B5 BD 14 D8 E0 B8 AE 0F 6D 69 2020-05-19 08:11:14.016 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 105: TransactionAdvance TO: DONE 2020-05-19 08:11:14.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:105 DONE 2020-05-19 08:11:14.019 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:14.020 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:14.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-05-19 08:11:14.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2020-05-19 08:11:14.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:14.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 105: Transaction event listener: DONE: DONE -> 2020-05-19 08:11:14.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:14.026 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:14.026 [TRACE] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 105 -- 2020-05-19 08:11:14.027 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 27: Node not awake! 2020-05-19 08:11:14.028 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@403e5b 2020-05-19 08:11:14.029 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:14.029 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: Node Init transaction completed with response COMPLETE 2020-05-19 08:11:14.030 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 22: Node not awake! 2020-05-19 08:11:14.030 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Encapsulating message, endpoint 0 2020-05-19 08:11:14.031 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:14.032 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY required on COMMAND_CLASS_USER_CODE 2020-05-19 08:11:14.032 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake! ==> /var/log/openhab2/events.log <== 2020-05-19 08:11:14.033 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:c9fd3b4d:node24' has been updated. 2020-05-19 08:11:14.035 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]] ==> /var/log/openhab2/openhab.log <== 2020-05-19 08:11:14.037 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: listening == false, frequentlyListening == false, awake == true 2020-05-19 08:11:14.038 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2020-05-19 08:11:14.040 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2020-05-19 08:11:14.041 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeInfo (0x60), type = Request 2020-05-19 08:11:14.042 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -126 2020-05-19 08:11:14.033 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_USER_CODE is required to be secured 2020-05-19 08:11:14.044 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 19 82 2020-05-19 08:11:14.045 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: ZWaveCommandClassTransactionPayload - send to node 2020-05-19 08:11:14.045 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 19 82 2020-05-19 08:11:14.050 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:14.051 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:14.051 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction Start type RequestNodeInfo 2020-05-19 08:11:14.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:14.053 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2020-05-19 08:11:14.054 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2020-05-19 08:11:14.055 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2020-05-19 08:11:14.056 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:14.057 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:16 CDT 2020 - 1999ms 2020-05-19 08:11:14.058 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:14.046 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Encapsulating message, endpoint 0 2020-05-19 08:11:14.059 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:14.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:14.060 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY required on COMMAND_CLASS_USER_CODE 2020-05-19 08:11:14.061 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:14.062 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:16 CDT 2020 - 1994ms 2020-05-19 08:11:14.061 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_USER_CODE is required to be secured 2020-05-19 08:11:14.066 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:14.066 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@783839 2020-05-19 08:11:14.065 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:14.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Bump transaction 111 priority from Config to Immediate 2020-05-19 08:11:14.069 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 2020-05-19 08:11:14.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue 2020-05-19 08:11:14.070 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:14.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:14.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 111 to queue - size 18 2020-05-19 08:11:14.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:14.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:14.075 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:14.075 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 60 01 9B 2020-05-19 08:11:14.077 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -101 2020-05-19 08:11:14.078 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:14.079 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:14.080 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:16 CDT 2020 - 1977ms 2020-05-19 08:11:14.081 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:14.082 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:14.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:14.084 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:14.086 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:14.087 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:14.089 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:16 CDT 2020 - 1968ms 2020-05-19 08:11:14.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:14.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:14.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:14.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:14.097 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:14.098 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:14.100 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:14.101 [TRACE] [lmessage.RequestNodeInfoMessageClass] - Handle RequestNodeInfo Response 2020-05-19 08:11:14.103 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack. 2020-05-19 08:11:14.104 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:14.105 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance WT: ApplicationUpdate {} 2020-05-19 08:11:14.106 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance RX: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:14.108 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance TO: WAIT_DATA 2020-05-19 08:11:14.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 106: Advanced to WAIT_DATA 2020-05-19 08:11:14.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 106: Transaction not completed 2020-05-19 08:11:14.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:14.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:14.114 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:14.116 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:14.117 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:39 CDT 2020 - 24993ms 2020-05-19 08:11:18.217 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:18.220 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 2020-05-19 08:11:18.222 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 06 00 49 81 00 00 31 2020-05-19 08:11:18.224 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 49 2020-05-19 08:11:18.225 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:18.229 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 81 00 00 2020-05-19 08:11:18.239 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:18.241 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:18.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:18.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:18.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:18.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 106: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.254 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 106: (Callback 0) 2020-05-19 08:11:18.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 106: callback 0 2020-05-19 08:11:18.258 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:18.259 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:18.261 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 25: Application update request. Node Info Request Failed. 2020-05-19 08:11:18.263 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction CANCELLED 2020-05-19 08:11:18.264 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance ST: CANCELLED 2020-05-19 08:11:18.266 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance WT: ApplicationUpdate {} 2020-05-19 08:11:18.268 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance RX: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:18.270 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance TO: CANCELLED 2020-05-19 08:11:18.271 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:18.273 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:18.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: CANCEL while sending message. Requeueing - 2 attempts left! 2020-05-19 08:11:18.276 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction RESET with 2 retries remaining. 2020-05-19 08:11:18.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Adding to device queue 2020-05-19 08:11:18.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Added 106 to queue - size 19 2020-05-19 08:11:18.281 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:18.283 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:18.284 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 27: Node not awake! 2020-05-19 08:11:18.286 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:18.288 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 22: Node not awake! 2020-05-19 08:11:18.289 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:18.291 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake! 2020-05-19 08:11:18.293 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: listening == false, frequentlyListening == false, awake == true 2020-05-19 08:11:18.294 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2020-05-19 08:11:18.296 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2020-05-19 08:11:18.298 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeInfo (0x60), type = Request 2020-05-19 08:11:18.299 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -126 2020-05-19 08:11:18.302 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 19 82 2020-05-19 08:11:18.304 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 19 82 2020-05-19 08:11:18.306 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:18.308 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction Start type RequestNodeInfo 2020-05-19 08:11:18.308 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:18.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.310 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2020-05-19 08:11:18.309 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:18.310 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2020-05-19 08:11:18.311 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:18.311 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2020-05-19 08:11:18.312 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:18.314 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:20 CDT 2020 - 1999ms 2020-05-19 08:11:18.315 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.316 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:18.317 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:20 CDT 2020 - 1995ms 2020-05-19 08:11:18.317 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:18.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 106: Transaction not completed 2020-05-19 08:11:18.320 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 2020-05-19 08:11:18.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:18.321 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.321 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 60 01 9B 2020-05-19 08:11:18.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:18.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:18.323 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -101 2020-05-19 08:11:18.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:18.324 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:18.325 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:18.325 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:18.326 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:18.327 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:20 CDT 2020 - 1985ms 2020-05-19 08:11:18.327 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:18.329 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:18.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:18.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:18.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:18.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:18.337 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:18.338 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:18.339 [TRACE] [lmessage.RequestNodeInfoMessageClass] - Handle RequestNodeInfo Response 2020-05-19 08:11:18.340 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack. 2020-05-19 08:11:18.341 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:18.342 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance WT: ApplicationUpdate {} 2020-05-19 08:11:18.343 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance RX: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:18.344 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance TO: WAIT_DATA 2020-05-19 08:11:18.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 106: Advanced to WAIT_DATA 2020-05-19 08:11:18.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 106: Transaction not completed 2020-05-19 08:11:18.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:18.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:18.350 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:18.351 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:18.352 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:43 CDT 2020 - 24994ms 2020-05-19 08:11:22.445 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:22.451 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 2020-05-19 08:11:22.453 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 06 00 49 81 00 00 31 2020-05-19 08:11:22.455 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 49 2020-05-19 08:11:22.459 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:22.462 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 81 00 00 2020-05-19 08:11:22.464 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:22.467 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:22.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:22.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:22.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:22.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 106: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 106: (Callback 0) 2020-05-19 08:11:22.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 106: callback 0 2020-05-19 08:11:22.506 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:22.507 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:22.510 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 25: Application update request. Node Info Request Failed. 2020-05-19 08:11:22.513 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction CANCELLED 2020-05-19 08:11:22.516 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance ST: CANCELLED 2020-05-19 08:11:22.519 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance WT: ApplicationUpdate {} 2020-05-19 08:11:22.522 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance RX: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:22.524 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance TO: CANCELLED 2020-05-19 08:11:22.526 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:22.528 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:22.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: CANCEL while sending message. Requeueing - 1 attempts left! 2020-05-19 08:11:22.531 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction RESET with 1 retries remaining. 2020-05-19 08:11:22.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Adding to device queue 2020-05-19 08:11:22.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Added 106 to queue - size 19 2020-05-19 08:11:22.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:22.538 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:22.540 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 27: Node not awake! 2020-05-19 08:11:22.542 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:22.543 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 22: Node not awake! 2020-05-19 08:11:22.545 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:22.547 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake! 2020-05-19 08:11:22.548 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: listening == false, frequentlyListening == false, awake == true 2020-05-19 08:11:22.549 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2020-05-19 08:11:22.550 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2020-05-19 08:11:22.551 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeInfo (0x60), type = Request 2020-05-19 08:11:22.553 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -126 2020-05-19 08:11:22.554 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 19 82 2020-05-19 08:11:22.555 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 19 82 2020-05-19 08:11:22.557 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:22.558 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:22.558 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction Start type RequestNodeInfo 2020-05-19 08:11:22.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.559 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:22.560 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2020-05-19 08:11:22.561 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2020-05-19 08:11:22.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:22.562 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2020-05-19 08:11:22.563 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:22.564 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:24 CDT 2020 - 1999ms 2020-05-19 08:11:22.565 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.566 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:22.568 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:24 CDT 2020 - 1995ms 2020-05-19 08:11:22.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 106: Transaction not completed 2020-05-19 08:11:22.569 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:22.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:22.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.572 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 2020-05-19 08:11:22.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:22.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:22.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:22.575 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 60 01 9B 2020-05-19 08:11:22.576 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:22.577 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -101 2020-05-19 08:11:22.577 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:22.579 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:24 CDT 2020 - 1985ms 2020-05-19 08:11:22.579 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:22.580 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:22.581 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:22.583 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:22.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:22.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:22.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:22.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 106: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:22.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:22.592 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:22.593 [TRACE] [lmessage.RequestNodeInfoMessageClass] - Handle RequestNodeInfo Response 2020-05-19 08:11:22.594 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack. 2020-05-19 08:11:22.595 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:22.596 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance WT: ApplicationUpdate {} 2020-05-19 08:11:22.597 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance RX: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:22.598 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance TO: WAIT_DATA 2020-05-19 08:11:22.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 106: Advanced to WAIT_DATA 2020-05-19 08:11:22.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 106: Transaction not completed 2020-05-19 08:11:22.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:22.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:22.603 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:22.604 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:22.605 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:47 CDT 2020 - 24995ms ==> /var/log/openhab2/events.log <== 2020-05-19 08:11:24.426 [vent.ItemStateChangedEvent] - Nw_Bedroom_Humidity changed from 41.4 to 41.5 ==> /var/log/openhab2/openhab.log <== 2020-05-19 08:11:24.677 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling... 2020-05-19 08:11:24.680 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:c9fd3b4d:node2:switch_binary 2020-05-19 08:11:24.682 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 0 2020-05-19 08:11:24.684 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_GET 2020-05-19 08:11:24.686 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 0 2020-05-19 08:11:24.688 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-05-19 08:11:24.689 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 2020-05-19 08:11:24.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:c9fd3b4d:node2:switch_binary on COMMAND_CLASS_BASIC 2020-05-19 08:11:24.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue 2020-05-19 08:11:24.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 112 to queue - size 19 2020-05-19 08:11:24.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:24.699 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:24.701 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:24.703 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:47 CDT 2020 - 22897ms 2020-05-19 08:11:26.637 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:26.642 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 2020-05-19 08:11:26.645 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 06 00 49 81 00 00 31 2020-05-19 08:11:26.647 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 49 2020-05-19 08:11:26.648 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:26.651 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 81 00 00 2020-05-19 08:11:26.652 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:26.654 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:26.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:26.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:26.661 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 106: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:26.662 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 106: [WAIT_DATA] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:26.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 106: (Callback 0) 2020-05-19 08:11:26.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 106: callback 0 2020-05-19 08:11:26.670 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:26.672 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:26.674 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 25: Application update request. Node Info Request Failed. 2020-05-19 08:11:26.676 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 106: Transaction CANCELLED 2020-05-19 08:11:26.678 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance ST: CANCELLED 2020-05-19 08:11:26.680 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance WT: ApplicationUpdate {} 2020-05-19 08:11:26.682 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance RX: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 2020-05-19 08:11:26.684 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 106: TransactionAdvance TO: CANCELLED 2020-05-19 08:11:26.685 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:26.687 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:26.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Retry count exceeded. Discarding message: TID 106: [CANCELLED] priority=Immediate, requiresResponse=true, callback: 0 2020-05-19 08:11:26.691 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: listening == false, frequentlyListening == false, awake == true 2020-05-19 08:11:26.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 106: Transaction completed 2020-05-19 08:11:26.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: notifyTransactionResponse TID:106 CANCELLED 2020-05-19 08:11:26.697 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:26.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 106: Transaction event listener: DONE: CANCELLED -> 2020-05-19 08:11:26.699 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:26.699 [TRACE] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 106 -- 2020-05-19 08:11:26.710 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: Node Init response (1) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1cb1320 2020-05-19 08:11:26.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:26.712 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 25: No data from device, but it was ACK'd. Possibly not supported? (Try 1) 2020-05-19 08:11:26.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:26.717 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:26.719 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 27: Node not awake! 2020-05-19 08:11:26.721 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:26.723 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 22: Node not awake! 2020-05-19 08:11:26.724 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:26.726 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake! 2020-05-19 08:11:26.727 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: listening == false, frequentlyListening == false, awake == true 2020-05-19 08:11:26.729 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2020-05-19 08:11:26.731 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2020-05-19 08:11:26.733 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 25: Creating empty message of class = SendData (0x13), type = Request 2020-05-19 08:11:26.734 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 28 2020-05-19 08:11:26.737 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 19 02 84 08 25 4B 1C 2020-05-19 08:11:26.739 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 09 00 13 19 02 84 08 25 4B 1C 2020-05-19 08:11:26.741 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-05-19 08:11:26.742 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: Transaction Start type SendData 2020-05-19 08:11:26.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 107: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:26.746 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2020-05-19 08:11:26.746 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-05-19 08:11:26.747 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 2020-05-19 08:11:26.748 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0 2020-05-19 08:11:26.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:26.750 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2020-05-19 08:11:26.752 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:26.752 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:26.754 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:28 CDT 2020 - 1999ms 2020-05-19 08:11:26.754 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-05-19 08:11:26.755 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 107: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:26.757 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:26.760 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:28 CDT 2020 - 1992ms 2020-05-19 08:11:26.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-05-19 08:11:26.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 107: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:26.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-05-19 08:11:26.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:26.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:26.769 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:26.766 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 2020-05-19 08:11:26.771 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24 2020-05-19 08:11:26.771 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:26.772 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:26.772 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:28 CDT 2020 - 1980ms 2020-05-19 08:11:26.775 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 2020-05-19 08:11:26.776 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:26.778 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:26.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:26.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:26.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 107: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:26.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:26.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 107: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:26.788 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:26.789 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE 2020-05-19 08:11:26.791 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response 2020-05-19 08:11:26.792 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: sentData successfully placed on stack. 2020-05-19 08:11:26.793 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance ST: WAIT_RESPONSE 2020-05-19 08:11:26.794 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance WT: null {} 2020-05-19 08:11:26.796 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-05-19 08:11:26.797 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance TO: WAIT_REQUEST 2020-05-19 08:11:26.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 107: Advanced to WAIT_REQUEST 2020-05-19 08:11:26.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 107: Transaction not completed 2020-05-19 08:11:26.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:26.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:26.803 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:26.806 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:26.808 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:31 CDT 2020 - 4992ms 2020-05-19 08:11:27.263 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling... 2020-05-19 08:11:27.264 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling deferred until initialisation complete 2020-05-19 08:11:28.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@ffdca 2020-05-19 08:11:28.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Bump transaction 113 priority from Controller to Immediate 2020-05-19 08:11:28.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Adding to device queue 2020-05-19 08:11:28.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Added 113 to queue - size 19 2020-05-19 08:11:28.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-05-19 08:11:28.851 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2020-05-19 08:11:28.853 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2020-05-19 08:11:28.855 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 19 08:11:31 CDT 2020 - 2944ms 2020-05-19 08:11:30.851 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF 2020-05-19 08:11:30.854 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4B 01 01 9A 3A 2020-05-19 08:11:30.856 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 4B 01 01 9A 3A 2020-05-19 08:11:30.857 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 58 2020-05-19 08:11:30.858 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched 2020-05-19 08:11:30.860 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 1: Message payload = 4B 01 01 9A 2020-05-19 08:11:30.862 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK 2020-05-19 08:11:30.865 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2020-05-19 08:11:30.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=75, payload=4B 01 01 9A 2020-05-19 08:11:30.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=75, payload=4B 01 01 9A 2020-05-19 08:11:30.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 107: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:30.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-05-19 08:11:30.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 107: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 75 2020-05-19 08:11:30.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 107: (Callback 75) 2020-05-19 08:11:30.877 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-05-19 08:11:30.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 107: callback 75 2020-05-19 08:11:30.879 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=75, payload=4B 01 01 9A 2020-05-19 08:11:30.881 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST 2020-05-19 08:11:30.882 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request 2020-05-19 08:11:30.883 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 75, Status = Transmission complete, no ACK received(1) 2020-05-19 08:11:30.884 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK. 2020-05-19 08:11:30.886 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance ST: WAIT_REQUEST 2020-05-19 08:11:30.887 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance WT: null {} 2020-05-19 08:11:30.890 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=1, callback=75, payload=4B 01 01 9A 2020-05-19 08:11:30.891 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance RQ: RREQ=true, RCLS=null 2020-05-19 08:11:30.892 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 107: TransactionAdvance TO: DONE 2020-05-19 08:11:30.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 107: Advanced to DONE 2020-05-19 08:11:30.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Response processed after 4152ms 2020-05-19 08:11:30.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 107: Transaction completed 2020-05-19 08:11:30.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: notifyTransactionResponse TID:107 DONE 2020-05-19 08:11:30.899 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2020-05-19 08:11:30.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 107: Transaction event listener: DONE: DONE -> 2020-05-19 08:11:30.900 [TRACE] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 107 -- 2020-05-19 08:11:30.904 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-05-19 08:11:30.905 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Went to sleep COMPLETE 2020-05-19 08:11:30.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-05-19 08:11:30.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-05-19 08:11:30.911 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:30.913 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 27: Node not awake! 2020-05-19 08:11:30.914 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == false, frequentlyListening == false, awake == false 2020-05-19 08:11:30.916 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 22: Node not awake!