chris:
log:set DEBUG opr.openhab.binding.zwave
My steps are:
Reset lock
Open Habmin
Go to Things and Start searching devices
In the lock. Initialize the inclousion mode by following the manual steps.
This is the debug log.
18:29:00.793 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:00.794 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:00.796 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00
18:29:00.798 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:00.798 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:00.801 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 5000ms
18:29:00.804 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 39: [WAIT_REQUEST] requiresResponse=true callback: 7
18:29:00.807 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:00.810 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 4991ms
18:29:00.813 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:00.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:00.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 4983ms
18:29:00.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00
18:29:00.823 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 39: [WAIT_REQUEST] requiresResponse=true callback: 7
18:29:00.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:29:00.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 39: [WAIT_REQUEST] requiresResponse=true callback: 7
18:29:00.827 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 39: (Callback 7)
18:29:00.829 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (7 <> 1)
18:29:00.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
18:29:00.832 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00
18:29:00.834 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
18:29:00.835 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
18:29:00.854 [INFO ] [smarthome.event.BindingEvent ] - org.openhab.binding.zwave.event.BindingEvent@69f906
18:29:00.853 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
18:29:00.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:00.859 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:00.860 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:00.862 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:00.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 4938ms
18:29:05.801 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
18:29:05.805 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 39: Timeout at state WAIT_REQUEST. 3 retries remaining.
18:29:05.809 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 39: Transaction is current transaction, so clearing!!!!!
18:29:05.813 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 39: Transaction CANCELLED
18:29:05.817 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:05.820 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:39 CANCELLED
18:29:05.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:05.832 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:29:05.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:29:05.841 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:29:05.845 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:29:05.849 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:29:05.853 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
18:29:05.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.546 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
18:29:22.551 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
18:29:22.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
18:29:22.559 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:29:22.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:22.567 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:29:22.573 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 01 08 BF
18:29:22.579 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 01 08 BF
18:29:22.583 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:29:22.585 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:29:22.587 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 40: Transaction Start type AddNodeToNetwork
18:29:22.589 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:22.591 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.594 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:22.596 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:29:22.599 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:22.601 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:22.603 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:29:22.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:22.608 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:29:22.610 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 5000ms
18:29:22.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:22.615 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:22.620 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.625 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4985ms
18:29:22.632 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:22.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.639 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4971ms
18:29:22.674 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 00 00 B5
18:29:22.678 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.681 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.684 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.688 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:29:22.690 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.692 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 40: (Callback 8)
18:29:22.694 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (8 <> 1)
18:29:22.696 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
18:29:22.699 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.701 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Done.
18:29:22.703 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
18:29:22.705 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
18:29:22.707 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
18:29:22.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
18:29:22.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:29:22.713 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:22.715 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:22.717 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.719 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4891ms
18:29:22.722 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller end exclusion
18:29:22.724 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWaveController include done
18:29:22.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:22.728 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:22.730 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:22.731 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.734 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4877ms
18:29:27.610 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
18:29:27.615 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 40: Timeout at state WAIT_REQUEST. 3 retries remaining.
18:29:27.618 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 40: Transaction is current transaction, so clearing!!!!!
18:29:27.622 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 40: Transaction CANCELLED
18:29:27.627 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:27.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:40 CANCELLED
18:29:27.640 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:27.645 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:29:27.650 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 00 09 BF
18:29:27.654 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 00 09 BF
18:29:27.658 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:29:27.660 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:29:27.661 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 41: Transaction Start type AddNodeToNetwork
18:29:27.663 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:27.664 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 41: [WAIT_REQUEST] requiresResponse=true callback: 9
18:29:27.667 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:27.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:29:27.670 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:27.676 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:29:27.679 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:29:27.680 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:27.682 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:27.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:27.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:27.693 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:27.699 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4994ms
18:29:27.704 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 41: [WAIT_REQUEST] requiresResponse=true callback: 9
18:29:27.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:27.715 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4979ms
18:29:27.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:27.722 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:27.725 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4968ms
18:29:28.505 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Requesting IsFailedNode status from controller.
18:29:28.508 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@72c789
18:29:28.511 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
18:29:28.514 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:29:28.516 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:28.519 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:28.522 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:28.525 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4168ms
18:29:32.693 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
18:29:32.698 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 41: Timeout at state WAIT_REQUEST. 3 retries remaining.
18:29:32.703 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 41: Transaction is current transaction, so clearing!!!!!
18:29:32.708 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 41: Transaction CANCELLED
18:29:32.714 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:32.719 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:41 CANCELLED
18:29:32.725 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:32.737 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:29:32.743 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:29:32.749 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:29:32.754 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:29:32.760 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:29:32.765 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:29:32.772 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 03 9A
18:29:32.779 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 03 9A
18:29:32.785 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:29:32.787 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:29:32.792 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:32.793 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:32.795 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:32.797 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:29:32.792 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: Transaction Start type IsFailedNodeID
18:29:32.799 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:29:32.801 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.802 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:32.805 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:29:32.804 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
18:29:32.808 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:32.810 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.806 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:32.813 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.811 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:32.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:32.820 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:34 ECT 2018 - 1998ms
18:29:32.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:32.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:34 ECT 2018 - 1991ms
18:29:32.828 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:32.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:32.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:34 ECT 2018 - 1985ms
18:29:32.834 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.837 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:29:32.839 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.841 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.843 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Is currently marked as failed by the controller!
18:29:32.845 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: Transaction COMPLETED
18:29:32.847 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance ST: DONE
18:29:32.849 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance WT: null {}
18:29:32.850 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance RX: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.852 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance TO: DONE
18:29:32.854 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 62ms
18:29:32.856 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 42: Transaction completed
18:29:32.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:42 DONE
18:29:32.860 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:32.861 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 42: Transaction event listener: DONE: DONE ->
18:29:32.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:32.864 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
18:29:32.865 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:32.877 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 42 --
18:29:32.878 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:29:32.879 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@d56a74
18:29:32.880 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:29:32.882 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE
18:29:32.883 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:29:32.885 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:29:32.887 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:29:32.889 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
18:29:32.890 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:30:02.885 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Requesting IsFailedNode status from controller.
18:30:02.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1136df3
18:30:02.892 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
18:30:02.895 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:30:02.899 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:30:02.904 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:30:02.909 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:30:02.914 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:30:02.919 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:30:02.924 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:30:02.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:30:02.935 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 03 9A
18:30:02.942 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 03 9A
18:30:02.948 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:30:02.947 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:30:02.954 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:30:02.955 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: Transaction Start type IsFailedNodeID
18:30:02.958 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:30:02.961 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:30:02.964 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:30:02.964 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
18:30:02.968 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:30:02.966 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:30:02.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:30:02.973 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:30:02.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:30:04 ECT 2018 - 2000ms
18:30:02.978 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:30:02.988 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:30:04 ECT 2018 - 1987ms
18:30:02.990 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:30:02.992 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.994 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.996 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Is currently marked as failed by the controller!
18:30:02.998 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: Transaction COMPLETED
18:30:03.000 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance ST: DONE
18:30:03.001 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance WT: null {}
18:30:03.003 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance RX: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:03.005 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance TO: DONE
18:30:03.007 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 52ms
18:30:03.009 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 43: Transaction completed
18:30:03.010 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:43 DONE
18:30:03.012 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:30:03.015 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 43: Transaction event listener: DONE: DONE ->
18:30:03.017 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:30:03.019 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:30:03.019 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
18:30:03.021 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:30:03.027 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 43 --
18:30:03.028 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:30:03.030 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1f16e13
18:30:03.031 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:30:03.032 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE
18:30:03.034 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:30:03.036 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:30:03.038 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
18:30:03.040 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
It seams that when i use the inclousion mode or not. I have the same log.