2017-02-08 05:52:54.665 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:false networkWide:false. 2017-02-08 05:52:54.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue 2017-02-08 05:52:54.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 24 2017-02-08 05:52:54.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:52:54.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:52:54.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:52:54.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:03 CST 2017 - 8683ms 2017-02-08 05:53:03.349 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions 2017-02-08 05:53:03.349 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 73: XXXXXXX Timeout at state WAIT_DATA. 3 retries remaining. 2017-02-08 05:53:03.349 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Transaction is current transaction, so clearing!!!!! 2017-02-08 05:53:03.349 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 175 CANCELLED 2017-02-08 05:53:03.349 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.349 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 73: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: notifyTransactionResponse 175 2017-02-08 05:53:03.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:03.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 175 2017-02-08 05:53:03.351 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:03.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:03.351 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: listening == true, frequentlyListening == false, awake == false 2017-02-08 05:53:03.351 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[66]] == [[66]] 2017-02-08 05:53:03.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2017-02-08 05:53:03.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:03.352 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 42 44 B4 2017-02-08 05:53:03.352 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 42 44 B4 2017-02-08 05:53:03.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 175 2017-02-08 05:53:03.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 175 2017-02-08 05:53:03.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 175 2017-02-08 05:53:03.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 175 2017-02-08 05:53:03.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 175 2017-02-08 05:53:03.354 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:03.354 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type RequestNodeNeighborUpdate 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:176 [WAIT_REQUEST] callback: 68 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 5000ms 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:176 [WAIT_REQUEST] callback: 68 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 5000ms 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 169 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 175 -- 175 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 175 -- DONE -- CANCELLED WAIT_DATA 2017-02-08 05:53:03.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: -- To notify -- TIMEOUT_WAITING_FOR_DATA 2017-02-08 05:53:03.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 176 -- 175 2017-02-08 05:53:03.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 175 -- 2017-02-08 05:53:03.356 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 73: Node Init response (1) TIMEOUT_WAITING_FOR_DATA 2017-02-08 05:53:03.356 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 73: No data from device, but it was ACK'd. Possibly not supported? (Try 1) 2017-02-08 05:53:03.357 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:03.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:176 [WAIT_REQUEST] callback: 68 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 4996ms 2017-02-08 05:53:03.546 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 44 21 D7 2017-02-08 05:53:03.546 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:03.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:03.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:176 [WAIT_REQUEST] callback: 68 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:176 [WAIT_REQUEST] callback: 68 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - checking transaction 68 (Callback 68) ...... 2017-02-08 05:53:03.547 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to transaction 68...... 2017-02-08 05:53:03.547 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:03.547 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 66: Got NodeNeighborUpdate request. 2017-02-08 05:53:03.547 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 66: NodeNeighborUpdate STARTED 2017-02-08 05:53:03.547 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: WAIT_REQUEST 2017-02-08 05:53:03.547 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:03.547 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:03.547 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:03.547 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: DONE 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction 68 advanced to DONE 2017-02-08 05:53:03.547 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[66]] == [[66]] 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Response processed after 193ms 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: **** Transaction completed 2017-02-08 05:53:03.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: notifyTransactionResponse 176 2017-02-08 05:53:03.548 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 176 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 176 2017-02-08 05:53:03.548 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 176 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 176 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 176 2017-02-08 05:53:03.548 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 176 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 176 2017-02-08 05:53:03.548 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 4C 00 00 03 37 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 176 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 176 2017-02-08 05:53:03.548 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 4C 00 00 03 37 2017-02-08 05:53:03.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 169 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 176 -- 176 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 176 -- DONE -- DONE UNINTIALIZED 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: -- To notify -- COMPLETE 2017-02-08 05:53:03.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 176 -- 2017-02-08 05:53:03.551 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:03.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.550 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:03.553 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type GetRoutingInfo 2017-02-08 05:53:03.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:169 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:03.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:03.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:03.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.552 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init response (0) COMPLETE 2017-02-08 05:53:03.554 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init transaction completed with response COMPLETE 2017-02-08 05:53:03.554 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 33 00 60 00 C0 6B 65 00 DF 43 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 1F 2017-02-08 05:53:03.554 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node advancer - advancing to GET_NEIGHBORS 2017-02-08 05:53:03.554 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent 2017-02-08 05:53:03.554 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2017-02-08 05:53:03.554 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node advancer: GET_NEIGHBORS - get RoutingInfo 2017-02-08 05:53:03.554 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 66: Request routing info 2017-02-08 05:53:03.554 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:03.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=33 00 60 00 C0 6B 65 00 DF 43 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:169 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@28565500 2017-02-08 05:53:03.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=33 00 60 00 C0 6B 65 00 DF 43 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.556 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is NOT the same 2017-02-08 05:53:03.556 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is NOT the same 2017-02-08 05:53:03.556 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is NOT the same 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 24 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1997ms 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1997ms 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:169 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=33 00 60 00 C0 6B 65 00 DF 43 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:169 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:03.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:169 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=33 00 60 00 C0 6B 65 00 DF 43 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.557 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 76: Got NodeRoutingInfo request. 2017-02-08 05:53:03.557 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 76: Neighbor nodes: 1 2 5 6 22 23 39 40 41 42 44 46 47 49 51 54 55 65 66 67 68 69 71 72 73 74 79 87 2017-02-08 05:53:03.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent 2017-02-08 05:53:03.557 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 76: Got an event from Z-Wave network: ZWaveNetworkEvent 2017-02-08 05:53:03.557 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 169 COMPLETED 2017-02-08 05:53:03.557 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: DONE 2017-02-08 05:53:03.557 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:03.557 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:03.557 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=33 00 60 00 C0 6B 65 00 DF 43 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.557 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: DONE 2017-02-08 05:53:03.558 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[76, 0, 0, 3]] == [[76, 0, 0, 3]] 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 5ms 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: **** Transaction completed 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse 169 2017-02-08 05:53:03.558 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 169 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:03.558 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue 2017-02-08 05:53:03.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:03.559 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 01 45 F4 2017-02-08 05:53:03.559 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 01 45 F4 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 169 2017-02-08 05:53:03.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 169 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 169 -- DONE -- DONE UNINTIALIZED 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 169 2017-02-08 05:53:03.560 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 178 -- 169 2017-02-08 05:53:03.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 169 -- 2017-02-08 05:53:03.561 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 76: Node Init response (0) COMPLETE 2017-02-08 05:53:03.562 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 76: Node Init transaction completed with response COMPLETE 2017-02-08 05:53:03.562 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 76: Node advancer - advancing to FAILED_CHECK 2017-02-08 05:53:03.562 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent 2017-02-08 05:53:03.562 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 76: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2017-02-08 05:53:03.562 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 76: Requesting IsFailedNode status from controller. 2017-02-08 05:53:03.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@5e00294b 2017-02-08 05:53:03.562 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:03.561 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type AddNodeToNetwork 2017-02-08 05:53:03.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:177 [WAIT_REQUEST] callback: 69 2017-02-08 05:53:03.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 5000ms 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:177 [WAIT_REQUEST] callback: 69 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 5000ms 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue 2017-02-08 05:53:03.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.563 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is NOT the same 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 24 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 5000ms 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:177 [WAIT_REQUEST] callback: 69 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.563 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 45 07 00 00 F0 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 4999ms 2017-02-08 05:53:03.564 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:03.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=7, callback=69, payload=45 07 00 00 2017-02-08 05:53:03.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=7, callback=69, payload=45 07 00 00 2017-02-08 05:53:03.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=7, callback=69, payload=45 07 00 00 2017-02-08 05:53:03.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:177 [WAIT_REQUEST] callback: 69 2017-02-08 05:53:03.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:03.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:177 [WAIT_REQUEST] callback: 69 2017-02-08 05:53:03.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - checking transaction 69 (Callback 69) ...... 2017-02-08 05:53:03.565 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2017-02-08 05:53:03.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to transaction 69...... 2017-02-08 05:53:03.565 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=7, callback=69, payload=45 07 00 00 2017-02-08 05:53:03.565 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed. 2017-02-08 05:53:03.565 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent 2017-02-08 05:53:03.565 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 177 CANCELLED 2017-02-08 05:53:03.565 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: CANCELLED 2017-02-08 05:53:03.565 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:03.565 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:03.565 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=7, callback=69, payload=45 07 00 00 2017-02-08 05:53:03.566 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: CANCELLED 2017-02-08 05:53:03.566 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.566 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[1]] == [[1]] 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: **** Transaction completed 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse 177 2017-02-08 05:53:03.566 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 177 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:03.566 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 177 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 177 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 177 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 177 2017-02-08 05:53:03.566 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 42 00 00 03 39 2017-02-08 05:53:03.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 177 2017-02-08 05:53:03.566 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 42 00 00 03 39 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 178 -- 177 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 179 -- 177 2017-02-08 05:53:03.567 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:03.567 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type GetRoutingInfo 2017-02-08 05:53:03.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:178 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:03.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:03.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:03.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:178 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.571 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:178 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1998ms 2017-02-08 05:53:03.573 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 3B 00 60 00 C0 7B 65 00 DD 5D 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3B 2017-02-08 05:53:03.574 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:03.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=3B 00 60 00 C0 7B 65 00 DD 5D 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=3B 00 60 00 C0 7B 65 00 DD 5D 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=3B 00 60 00 C0 7B 65 00 DD 5D 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:178 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:03.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:178 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.575 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=3B 00 60 00 C0 7B 65 00 DD 5D 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.575 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 66: Got NodeRoutingInfo request. 2017-02-08 05:53:03.575 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 66: Neighbor nodes: 1 2 4 5 6 22 23 39 40 41 42 44 45 46 47 49 51 54 55 65 67 68 69 71 72 73 75 76 77 79 86 87 2017-02-08 05:53:03.575 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent 2017-02-08 05:53:03.575 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveNetworkEvent 2017-02-08 05:53:03.575 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 178 COMPLETED 2017-02-08 05:53:03.575 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: DONE 2017-02-08 05:53:03.575 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:03.575 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:03.576 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=GetRoutingInfo[0x80], type=Response[0x01], dest=255, callback=0, payload=3B 00 60 00 C0 7B 65 00 DD 5D 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2017-02-08 05:53:03.576 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: DONE 2017-02-08 05:53:03.576 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[66, 0, 0, 3]] == [[66, 0, 0, 3]] 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 9ms 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: **** Transaction completed 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse 178 2017-02-08 05:53:03.576 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:03.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 178 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 178 2017-02-08 05:53:03.576 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 4C D5 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 178 2017-02-08 05:53:03.576 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 4C D5 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 178 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 178 2017-02-08 05:53:03.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 178 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 178 -- DONE -- DONE UNINTIALIZED 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 179 -- 178 2017-02-08 05:53:03.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 178 -- 2017-02-08 05:53:03.578 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:03.578 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type IsFailedNodeID 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:179 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.578 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init response (0) COMPLETE 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:179 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1999ms 2017-02-08 05:53:03.578 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init transaction completed with response COMPLETE 2017-02-08 05:53:03.579 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node advancer - advancing to DELETE_SUC_ROUTES 2017-02-08 05:53:03.579 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent 2017-02-08 05:53:03.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2017-02-08 05:53:03.579 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node advancer is deleting SUC return route. 2017-02-08 05:53:03.579 [DEBUG] [age.DeleteSucReturnRouteMessageClass] - NODE 66: Deleting SUC return routes 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@3c08e330 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Adding to device queue 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Added to queue - size 22 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1999ms 2017-02-08 05:53:03.580 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:179 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.580 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 00 98 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1997ms 2017-02-08 05:53:03.581 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=00 2017-02-08 05:53:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=00 2017-02-08 05:53:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=00 2017-02-08 05:53:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:179 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:03.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:179 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:03.582 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=00 2017-02-08 05:53:03.582 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 76: Is currently marked as healthy by the controller 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 179 COMPLETED 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: DONE 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=00 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: DONE 2017-02-08 05:53:03.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[76]] == [[76]] 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 5ms 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: **** Transaction completed 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse 179 2017-02-08 05:53:03.583 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:03.583 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 179 2017-02-08 05:53:03.583 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: listening == true, frequentlyListening == false, awake == false 2017-02-08 05:53:03.583 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[66]] == [[66]] 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 179 2017-02-08 05:53:03.583 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 55 42 46 AB 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 179 2017-02-08 05:53:03.583 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 55 42 46 AB 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 179 2017-02-08 05:53:03.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 179 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 179 -- DONE -- DONE UNINTIALIZED 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 180 -- 179 2017-02-08 05:53:03.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 179 -- 2017-02-08 05:53:03.585 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 76: Node Init response (0) COMPLETE 2017-02-08 05:53:03.585 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 76: Node Init transaction completed with response COMPLETE 2017-02-08 05:53:03.585 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 76: Node advancer - advancing to REQUEST_NIF 2017-02-08 05:53:03.585 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent 2017-02-08 05:53:03.585 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 76: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2017-02-08 05:53:03.585 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:03.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 76: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@19c49683 2017-02-08 05:53:03.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.587 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:03.587 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type DeleteSUCReturnRoute 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:180 [WAIT_RESPONSE] callback: 70 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:180 [WAIT_RESPONSE] callback: 70 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 76: Adding to device queue 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:03.587 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction node Id is different 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 76: Added to queue - size 22 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:180 [WAIT_RESPONSE] callback: 70 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 2000ms 2017-02-08 05:53:03.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:05 CST 2017 - 1999ms 2017-02-08 05:53:03.591 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 55 01 AE 2017-02-08 05:53:03.591 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:03.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=DeleteSUCReturnRoute[0x55], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:03.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=DeleteSUCReturnRoute[0x55], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=DeleteSUCReturnRoute[0x55], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:180 [WAIT_RESPONSE] callback: 70 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:180 [WAIT_RESPONSE] callback: 70 2017-02-08 05:53:03.592 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=DeleteSUCReturnRoute[0x55], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:03.592 [DEBUG] [age.DeleteSucReturnRouteMessageClass] - NODE 66: Got DeleteSUCReturnRoute response. 2017-02-08 05:53:03.592 [DEBUG] [age.DeleteSucReturnRouteMessageClass] - NODE 66: DeleteSUCReturnRoute command in progress. 2017-02-08 05:53:03.592 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: WAIT_RESPONSE 2017-02-08 05:53:03.592 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:03.592 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:03.592 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=DeleteSUCReturnRoute[0x55], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:03.592 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: WAIT_REQUEST 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction 70 advanced to WAIT_REQUEST 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: **** Transaction not completed 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:03.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 5000ms 2017-02-08 05:53:05.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@12ed0a18 2017-02-08 05:53:05.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: Adding to device queue 2017-02-08 05:53:05.805 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction node Id is different 2017-02-08 05:53:05.805 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction node Id is different 2017-02-08 05:53:05.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: Added to queue - size 22 2017-02-08 05:53:05.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:05.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:05.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:05.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 2787ms 2017-02-08 05:53:06.627 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 55 46 01 E8 2017-02-08 05:53:06.628 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=DeleteSUCReturnRoute[0x55], type=Request[0x00], dest=1, callback=70, payload=46 01 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=DeleteSUCReturnRoute[0x55], type=Request[0x00], dest=1, callback=70, payload=46 01 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=DeleteSUCReturnRoute[0x55], type=Request[0x00], dest=1, callback=70, payload=46 01 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:180 [WAIT_REQUEST] callback: 70 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:180 [WAIT_REQUEST] callback: 70 2017-02-08 05:53:06.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - checking transaction 70 (Callback 70) ...... 2017-02-08 05:53:06.630 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2017-02-08 05:53:06.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to transaction 70...... 2017-02-08 05:53:06.630 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=DeleteSUCReturnRoute[0x55], type=Request[0x00], dest=1, callback=70, payload=46 01 2017-02-08 05:53:06.630 [DEBUG] [age.DeleteSucReturnRouteMessageClass] - NODE 66: Got DeleteSUCReturnRoute request. 2017-02-08 05:53:06.630 [DEBUG] [age.DeleteSucReturnRouteMessageClass] - NODE 66: Delete SUC return routes failed. 2017-02-08 05:53:06.630 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent 2017-02-08 05:53:06.630 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveNetworkEvent 2017-02-08 05:53:06.630 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 180 COMPLETED 2017-02-08 05:53:06.630 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: DONE 2017-02-08 05:53:06.630 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:06.630 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: null 2017-02-08 05:53:06.630 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=DeleteSUCReturnRoute[0x55], type=Request[0x00], dest=1, callback=70, payload=46 01 2017-02-08 05:53:06.631 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: DONE 2017-02-08 05:53:06.631 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[66]] == [[66]] 2017-02-08 05:53:06.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Response processed after 3044ms 2017-02-08 05:53:06.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: **** Transaction completed 2017-02-08 05:53:06.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: notifyTransactionResponse 180 2017-02-08 05:53:06.631 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:06.631 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2017-02-08 05:53:06.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:06.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 180 2017-02-08 05:53:06.632 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 79: listening == false, frequentlyListening == false, awake == false 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Node not awake! 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 180 2017-02-08 05:53:06.632 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 76: listening == true, frequentlyListening == false, awake == false 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 180 2017-02-08 05:53:06.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction node Id is different 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 180 2017-02-08 05:53:06.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transaction payload is the same [[76]] == [[76]] 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 180 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 180 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 180 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 180 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 180 2017-02-08 05:53:06.632 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 4C D7 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 180 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 180 2017-02-08 05:53:06.632 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 4C D7 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 180 2017-02-08 05:53:06.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 27 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 28 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 29 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 30 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 33 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 49 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 171 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 180 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 180 -- DONE -- DONE UNINTIALIZED 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: -- To notify -- COMPLETE 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 181 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 182 -- 180 2017-02-08 05:53:06.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 180 -- 2017-02-08 05:53:06.643 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2017-02-08 05:53:06.643 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init response (0) COMPLETE 2017-02-08 05:53:06.643 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2017-02-08 05:53:06.643 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init transaction completed with response COMPLETE 2017-02-08 05:53:06.643 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type RequestNodeInfo 2017-02-08 05:53:06.643 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node advancer - advancing to SUC_ROUTE 2017-02-08 05:53:06.643 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent 2017-02-08 05:53:06.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:06.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:181 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:06.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:06.643 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2017-02-08 05:53:06.644 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node advancer is setting SUC route. 2017-02-08 05:53:06.644 [DEBUG] [age.AssignSucReturnRouteMessageClass] - NODE 66: Assigning SUC return route 2017-02-08 05:53:06.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@380e2adf 2017-02-08 05:53:06.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null 2017-02-08 05:53:06.645 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 2000ms 2017-02-08 05:53:06.645 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:181 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:06.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Adding to device queue 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 1999ms 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Added to queue - size 22 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload= 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:181 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:181 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:06.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:181 [WAIT_RESPONSE] callback: 0 2017-02-08 05:53:06.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:06.647 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:06.647 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack. 2017-02-08 05:53:06.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:08 CST 2017 - 1998ms 2017-02-08 05:53:06.647 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: WAIT_RESPONSE 2017-02-08 05:53:06.647 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null 2017-02-08 05:53:06.647 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: ApplicationUpdate 2017-02-08 05:53:06.647 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 2017-02-08 05:53:06.648 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: WAIT_DATA 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction 0 advanced to WAIT_DATA 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 76: **** Transaction not completed 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:06.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:31 CST 2017 - 25000ms 2017-02-08 05:53:08.366 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 44 21 D7 2017-02-08 05:53:08.367 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:08.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:08.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:08.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:08.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:181 [WAIT_DATA] callback: 0 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:181 [WAIT_DATA] callback: 0 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - checking transaction 0 (Callback 0) ...... 2017-02-08 05:53:08.369 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - NO callback match! (0 <> 68) 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated 2017-02-08 05:53:08.369 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=33, callback=68, payload=44 21 2017-02-08 05:53:08.369 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NodeNeighborUpdate request without transaction 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:08.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:08.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:08.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:31 CST 2017 - 23278ms 2017-02-08 05:53:13.672 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 44 22 D4 2017-02-08 05:53:13.673 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6 2017-02-08 05:53:13.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=34, callback=68, payload=44 22 2017-02-08 05:53:13.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=34, callback=68, payload=44 22 2017-02-08 05:53:13.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=34, callback=68, payload=44 22 2017-02-08 05:53:13.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:181 [WAIT_DATA] callback: 0 2017-02-08 05:53:13.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2017-02-08 05:53:13.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:181 [WAIT_DATA] callback: 0 2017-02-08 05:53:13.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - checking transaction 0 (Callback 0) ...... 2017-02-08 05:53:13.675 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - NO callback match! (0 <> 68) 2017-02-08 05:53:13.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated 2017-02-08 05:53:13.675 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[0x48], type=Request[0x00], dest=34, callback=68, payload=44 22 2017-02-08 05:53:13.675 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NodeNeighborUpdate request without transaction 2017-02-08 05:53:13.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2017-02-08 05:53:13.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:13.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:13.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:13.676 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:31 CST 2017 - 17972ms 2017-02-08 05:53:24.666 [DEBUG] [ve.internal.protocol.ZWaveController] - Ending inclusion mode. 2017-02-08 05:53:24.666 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer. 2017-02-08 05:53:24.666 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode. 2017-02-08 05:53:24.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue 2017-02-08 05:53:24.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 23 2017-02-08 05:53:24.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start 2017-02-08 05:53:24.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding... 2017-02-08 05:53:24.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer 2017-02-08 05:53:24.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Feb 08 05:53:31 CST 2017 - 6981ms 2017-02-08 05:53:24.667 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end inclusion 2017-02-08 05:53:31.648 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions 2017-02-08 05:53:31.648 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 76: XXXXXXX Timeout at state WAIT_DATA. 3 retries remaining. 2017-02-08 05:53:31.648 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Transaction is current transaction, so clearing!!!!! 2017-02-08 05:53:31.648 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 181 CANCELLED 2017-02-08 05:53:31.648 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2017-02-08 05:53:31.648 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 76: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2017-02-08 05:53:31.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 76: notifyTransactionResponse 181 2017-02-08 05:53:31.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start