Zwave devices do not appear in inbox which have already been connected - debug log available

Hi,
I am getting a bit frustrated because very simple things don’t work. But maybe you can help me:
I hab an OH 2 instance a few years ago.

Now I installed the newest OH3 on a raspberry. With a zwave controller dongle. As devices i have a magnetic switch a fibaro socket and a LED ligthbulb.

Yesterday a added the zwave binding, created the Controller dongle as a Bridge:
All three devices appeared in the inbox. But have not been recognized (Noder 002, Node 003, Node 004).
Looking back, i should just have waited longer till inclusin was completed.
I added one of them to see what happens, but deleted the item again.

Today I wanted to try again, but after reading more i think my controller and devices are in a limbo / undefined state.
No new devices apper in my inbox.
The switch i am trying to intergrate gets aparently recognized, when i start the “Scan” in openhab (see logfile domitech_ze27_00_000).
But the item does not apear in the inbox.
As you can see in the logfile the item gets recognizes, but my openhab does not promt it to me in the “Inbox”
Maybee because i added the LED which is working with uid “zwave:device:ZWaveBridge:node2” and now it is double?

2022-05-13 19:17:08.026 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:domitech_ze27_00_000

It is all a bit confusing now, so some of my questions are:
If i click “Scan” under “Ad New Thing->zwaveBinding”, does this set my zwave controller to inclusion mode?
How do i get my controller to exclusion mode?

If item appear as NODE 003 in the inbox:
Should i add them as item, or wait until they are recognized correctly?

Any tips on how to reset all the mess and get all of it working again?

==> /var/log/openhab/events.log <==

2022-05-13 19:16:35.080 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Switch' received command OFF

2022-05-13 19:16:35.083 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch' predicted to become OFF

2022-05-13 19:16:35.092 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch' changed from ON to OFF

==> /var/log/openhab/openhab.log <==

2022-05-13 19:16:36.645 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...

2022-05-13 19:16:36.648 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:ZWaveBridge:node2:switch_dimmer

2022-05-13 19:16:36.650 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2022-05-13 19:16:36.652 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET

2022-05-13 19:16:36.656 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:16:36.658 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2022-05-13 19:16:36.661 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:ZWaveBridge:node2:switch_dimmer on COMMAND_CLASS_BASIC

2022-05-13 19:16:36.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue

2022-05-13 19:16:36.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 145 to queue - size 1

2022-05-13 19:16:36.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:16:36.673 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 81 65 

2022-05-13 19:16:36.677 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 81 65 

2022-05-13 19:16:36.680 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:16:36.682 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:16:36.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:16:36.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 145: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:16:36.689 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2022-05-13 19:16:36.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 145: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:16:36.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:16:36.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:16:36.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 145: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:16:36.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 145: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.707 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:16:36.709 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.

2022-05-13 19:16:36.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 145: Advanced to WAIT_REQUEST

2022-05-13 19:16:36.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 145: Transaction not completed

2022-05-13 19:16:36.717 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 26 03 30 E6 

2022-05-13 19:16:36.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:16:36.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2022-05-13 19:16:36.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 26 03 30 

2022-05-13 19:16:36.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 26 03 30 

2022-05-13 19:16:36.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 145: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)

2022-05-13 19:16:36.733 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:16:36.735 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2022-05-13 19:16:36.738 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:16:36.741 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT

2022-05-13 19:16:36.744 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 48

2022-05-13 19:16:36.747 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2022-05-13 19:16:36.750 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=48

2022-05-13 19:16:36.754 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:ZWaveBridge:node2:switch_dimmer to 48 [PercentType]

2022-05-13 19:16:36.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.

2022-05-13 19:16:36.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1437225.

2022-05-13 19:16:36.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2022-05-13 19:16:36.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2022-05-13 19:16:36.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:16:36.772 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 81 00 00 08 62 

2022-05-13 19:16:36.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=129, payload=81 00 00 08 

2022-05-13 19:16:36.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2022-05-13 19:16:36.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=129, payload=81 00 00 08 

2022-05-13 19:16:36.783 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 26 03 2E F8 

2022-05-13 19:16:36.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 145: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:16:36.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 26 03 2E 

2022-05-13 19:16:36.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 145: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 129

2022-05-13 19:16:36.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 145: (Callback 129)

2022-05-13 19:16:36.796 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2022-05-13 19:16:36.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 145: callback 129

2022-05-13 19:16:36.801 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=129, payload=81 00 00 08 

2022-05-13 19:16:36.804 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 129, Status = Transmission complete and ACK received(0)

2022-05-13 19:16:36.807 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:16:36.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 145: Advanced to WAIT_DATA

2022-05-13 19:16:36.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 145: Transaction not completed

2022-05-13 19:16:36.816 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 26 03 2E 

2022-05-13 19:16:36.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2022-05-13 19:16:36.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)

2022-05-13 19:16:36.823 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:16:36.826 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2022-05-13 19:16:36.829 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:16:36.831 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT

2022-05-13 19:16:36.834 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 46

2022-05-13 19:16:36.836 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2022-05-13 19:16:36.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=46

2022-05-13 19:16:36.842 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:ZWaveBridge:node2:switch_dimmer to 46 [PercentType]

2022-05-13 19:16:36.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.

2022-05-13 19:16:36.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ea0bf2.

2022-05-13 19:16:36.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ea0bf2.

2022-05-13 19:16:36.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:145 DONE

2022-05-13 19:16:36.859 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2022-05-13 19:16:36.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2022-05-13 19:16:36.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2022-05-13 19:16:36.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:16:36.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:17:05.965 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:ZWaveBridge

2022-05-13 19:17:05.968 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do

2022-05-13 19:17:05.970 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:ZWaveBridge

2022-05-13 19:17:05.973 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2

2022-05-13 19:17:05.977 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.

2022-05-13 19:17:05.980 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion

2022-05-13 19:17:05.983 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.

2022-05-13 19:17:05.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 146 to queue - size 1

2022-05-13 19:17:05.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:17:05.993 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 82 F3 

2022-05-13 19:17:05.997 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 82 F3 

2022-05-13 19:17:06.000 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:17:06.002 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:17:06.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 146: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 130

2022-05-13 19:17:06.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:17:06.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:17:06.010 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 82 01 00 00 31 

2022-05-13 19:17:06.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 146: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 130

2022-05-13 19:17:06.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:17:06.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=130, payload=82 01 00 00 

2022-05-13 19:17:06.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=130, payload=82 01 00 00 

2022-05-13 19:17:06.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 146: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 130

2022-05-13 19:17:06.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:17:06.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 146: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 130

2022-05-13 19:17:06.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 146: (Callback 130)

2022-05-13 19:17:06.035 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2022-05-13 19:17:06.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 146: callback 130

2022-05-13 19:17:06.041 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=130, payload=82 01 00 00 

2022-05-13 19:17:06.045 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.

2022-05-13 19:17:06.048 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart

2022-05-13 19:17:06.051 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 146: Transaction COMPLETED

2022-05-13 19:17:06.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 50ms

2022-05-13 19:17:06.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 146: Transaction completed

2022-05-13 19:17:06.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:146 DONE

2022-05-13 19:17:06.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:17:06.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:17:08.008 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed

2022-05-13 19:17:08.026 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:domitech_ze27_00_000

2022-05-13 19:18:05.971 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:ZWaveBridge

2022-05-13 19:18:05.974 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart

2022-05-13 19:18:05.976 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.

2022-05-13 19:18:05.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 147 to queue - size 1

2022-05-13 19:18:05.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:18:05.985 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 83 36 

2022-05-13 19:18:05.988 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 83 36 

2022-05-13 19:18:05.991 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:18:05.992 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:18:05.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:18:05.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 147: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 131

2022-05-13 19:18:05.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:18:06.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2022-05-13 19:18:06.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:18:06.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:18:06.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2022-05-13 19:18:06.143 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 83 06 02 00 35 

2022-05-13 19:18:06.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=131, payload=83 06 02 00 

2022-05-13 19:18:06.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=131, payload=83 06 02 00 

2022-05-13 19:18:06.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 147: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 131

2022-05-13 19:18:06.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:18:06.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 147: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 131

2022-05-13 19:18:06.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 147: (Callback 131)

2022-05-13 19:18:06.163 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2022-05-13 19:18:06.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 147: callback 131

2022-05-13 19:18:06.168 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=131, payload=83 06 02 00 

2022-05-13 19:18:06.171 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.

2022-05-13 19:18:06.174 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovered

2022-05-13 19:18:06.181 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInclusionEvent

2022-05-13 19:18:06.184 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone

2022-05-13 19:18:06.186 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.

2022-05-13 19:18:06.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 148 to queue - size 1

2022-05-13 19:18:06.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2022-05-13 19:18:06.194 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion

2022-05-13 19:18:06.197 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done

2022-05-13 19:18:06.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 147: Advanced to DONE

2022-05-13 19:18:06.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 204ms

2022-05-13 19:18:06.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 147: Transaction completed

2022-05-13 19:18:06.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:147 DONE

2022-05-13 19:18:06.211 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:18:06.214 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:18:06.217 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 

2022-05-13 19:18:06.220 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 

2022-05-13 19:18:06.223 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:18:06.225 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:18:06.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 148: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0

2022-05-13 19:18:06.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:18:06.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:18:06.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 148: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0

2022-05-13 19:18:06.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:18:06.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:18:06.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2022-05-13 19:18:11.229 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 148: Timeout at state WAIT_REQUEST. 3 retries remaining.

2022-05-13 19:18:11.233 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 148: Transaction is current transaction, so clearing!!!!!

2022-05-13 19:18:11.235 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 148: Transaction CANCELLED

2022-05-13 19:18:11.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:148 CANCELLED

2022-05-13 19:18:11.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:29:58.065 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:ZWaveBridge

2022-05-13 19:32:19.259 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:ZWaveBridge:node2:switch_dimmer --> ON [OnOffType]

2022-05-13 19:32:19.263 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_SET

2022-05-13 19:32:19.266 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:32:19.268 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2022-05-13 19:32:19.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue

2022-05-13 19:32:19.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 149 to queue - size 1

2022-05-13 19:32:19.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:32:19.280 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 26 01 FF 25 85 9F 

2022-05-13 19:32:19.284 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 26 01 FF 25 85 9F 

2022-05-13 19:32:19.287 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:32:19.289 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:32:19.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 149: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133

2022-05-13 19:32:19.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:32:19.294 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:32:19.296 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 1800 seconds - start in 1500 milliseconds.

2022-05-13 19:32:19.296 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2022-05-13 19:32:19.297 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 149: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133

2022-05-13 19:32:19.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:19.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:32:19.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:32:19.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2022-05-13 19:32:19.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:19.311 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 149: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133

2022-05-13 19:32:19.313 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 85 00 00 03 6D 

2022-05-13 19:32:19.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:32:19.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 149: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133

2022-05-13 19:32:19.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=133, payload=85 00 00 03 

2022-05-13 19:32:19.320 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:19.323 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.

2022-05-13 19:32:19.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 149: Advanced to WAIT_REQUEST

2022-05-13 19:32:19.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 149: Transaction not completed

2022-05-13 19:32:19.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=133, payload=85 00 00 03 

2022-05-13 19:32:19.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 149: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 133

2022-05-13 19:32:19.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:32:19.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 149: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 133

2022-05-13 19:32:19.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 149: (Callback 133)

2022-05-13 19:32:19.344 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2022-05-13 19:32:19.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 149: callback 133

2022-05-13 19:32:19.349 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=133, payload=85 00 00 03 

2022-05-13 19:32:19.352 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 133, Status = Transmission complete and ACK received(0)

2022-05-13 19:32:19.355 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:32:19.357 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 149: Transaction COMPLETED

2022-05-13 19:32:19.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Response processed after 70ms

2022-05-13 19:32:19.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 149: Transaction completed

2022-05-13 19:32:19.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:149 DONE

2022-05-13 19:32:19.373 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2022-05-13 19:32:19.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:32:19.378 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

==> /var/log/openhab/events.log <==

2022-05-13 19:32:19.220 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Switch' received command ON

2022-05-13 19:32:19.226 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Switch' predicted to become ON

2022-05-13 19:32:19.235 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Switch' changed from OFF to ON

==> /var/log/openhab/openhab.log <==

2022-05-13 19:32:20.794 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...

2022-05-13 19:32:20.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:ZWaveBridge:node2:switch_dimmer

2022-05-13 19:32:20.799 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2022-05-13 19:32:20.801 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET

2022-05-13 19:32:20.803 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:32:20.806 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2022-05-13 19:32:20.809 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:ZWaveBridge:node2:switch_dimmer on COMMAND_CLASS_BASIC

2022-05-13 19:32:20.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue

2022-05-13 19:32:20.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 150 to queue - size 1

2022-05-13 19:32:20.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:32:20.822 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 86 62 

2022-05-13 19:32:20.825 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 86 62 

2022-05-13 19:32:20.828 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:32:20.830 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:32:20.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 150: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 134

2022-05-13 19:32:20.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:32:20.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:32:20.838 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2022-05-13 19:32:20.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 150: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 134

2022-05-13 19:32:20.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:32:20.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:20.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:20.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 150: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 134

2022-05-13 19:32:20.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:32:20.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 150: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 134

2022-05-13 19:32:20.853 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 86 00 00 02 6F 

2022-05-13 19:32:20.855 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:20.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=134, payload=86 00 00 02 

2022-05-13 19:32:20.859 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.

2022-05-13 19:32:20.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 150: Advanced to WAIT_REQUEST

2022-05-13 19:32:20.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 150: Transaction not completed

2022-05-13 19:32:20.865 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 26 03 34 E2 

2022-05-13 19:32:20.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=134, payload=86 00 00 02 

2022-05-13 19:32:20.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 26 03 34 

2022-05-13 19:32:20.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 150: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 134

2022-05-13 19:32:20.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:32:20.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 150: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 134

2022-05-13 19:32:20.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 150: (Callback 134)

2022-05-13 19:32:20.881 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2022-05-13 19:32:20.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 150: callback 134

2022-05-13 19:32:20.886 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=134, payload=86 00 00 02 

2022-05-13 19:32:20.889 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 134, Status = Transmission complete and ACK received(0)

2022-05-13 19:32:20.892 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:32:20.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 150: Advanced to WAIT_DATA

2022-05-13 19:32:20.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 150: Transaction not completed

2022-05-13 19:32:20.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 26 03 34 

2022-05-13 19:32:20.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2022-05-13 19:32:20.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)

2022-05-13 19:32:20.908 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:32:20.911 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2022-05-13 19:32:20.914 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:32:20.917 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT

2022-05-13 19:32:20.921 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 52

2022-05-13 19:32:20.924 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2022-05-13 19:32:20.928 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=52

2022-05-13 19:32:20.931 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:ZWaveBridge:node2:switch_dimmer to 52 [PercentType]

2022-05-13 19:32:20.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.

2022-05-13 19:32:20.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@122928c.

2022-05-13 19:32:20.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@122928c.

2022-05-13 19:32:20.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:150 DONE

2022-05-13 19:32:20.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2022-05-13 19:32:20.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2022-05-13 19:32:20.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2022-05-13 19:32:20.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:32:20.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:32:21.326 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:ZWaveBridge:node2:switch_dimmer --> OFF [OnOffType]

2022-05-13 19:32:21.329 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_SET

2022-05-13 19:32:21.331 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported

2022-05-13 19:32:21.334 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2022-05-13 19:32:21.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue

2022-05-13 19:32:21.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 151 to queue - size 1

2022-05-13 19:32:21.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2022-05-13 19:32:21.347 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 26 01 00 25 87 62 

2022-05-13 19:32:21.350 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 26 01 00 25 87 62 

2022-05-13 19:32:21.354 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2022-05-13 19:32:21.356 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2022-05-13 19:32:21.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 151: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135

2022-05-13 19:32:21.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:32:21.361 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 1800 seconds - start in 1500 milliseconds.

2022-05-13 19:32:21.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2022-05-13 19:32:21.364 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2022-05-13 19:32:21.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 151: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135

2022-05-13 19:32:21.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:21.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2022-05-13 19:32:21.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:21.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 151: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135

2022-05-13 19:32:21.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:32:21.378 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 151: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135

2022-05-13 19:32:21.379 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 87 00 00 02 6E 

2022-05-13 19:32:21.381 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2022-05-13 19:32:21.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=135, payload=87 00 00 02 

2022-05-13 19:32:21.384 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.

2022-05-13 19:32:21.387 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 151: Advanced to WAIT_REQUEST

2022-05-13 19:32:21.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 151: Transaction not completed

2022-05-13 19:32:21.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=135, payload=87 00 00 02 

2022-05-13 19:32:21.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 151: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 135

2022-05-13 19:32:21.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2022-05-13 19:32:21.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 151: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 135

2022-05-13 19:32:21.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 151: (Callback 135)

2022-05-13 19:32:21.405 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2022-05-13 19:32:21.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 151: callback 135

2022-05-13 19:32:21.411 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=135, payload=87 00 00 02 

2022-05-13 19:32:21.414 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 135, Status = Transmission complete and ACK received(0)

2022-05-13 19:32:21.416 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false

2022-05-13 19:32:21.419 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 151: Transaction COMPLETED

2022-05-13 19:32:21.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Response processed after 65ms

2022-05-13 19:32:21.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 151: Transaction completed

2022-05-13 19:32:21.426 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:151 DONE

2022-05-13 19:32:21.431 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2022-05-13 19:32:21.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2022-05-13 19:32:21.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.


Yes. The length of time for inclusion is on the Controller UI page. (click the advanced tab to see it).

Also on the Controller UI page use Exclude Devices then click the action button on your device per your manual (or do whatever the manual says for exclusion)

I do not believe that is necessary. The binding keeps going on the initialization.

Some questions for you

  1. What version of the newest OH3 (3.2, 3.3M5, or a daily snapshot)?
  2. What kind of Zstick and Rpi? There is an issue with Aeotec ZStick on Rpi4 I would like to rule out.
  3. If aeotec, did you include with the button or with the device in the Rpi? If you included while not plugged in you will need to do the Zwave Scan to get in the inbox
  4. Obviously the light is mains powered, but are the other devices battery? Those take longer to initialize.

Hard to say what to do next at this point.

Bob

Also under the advanced tab on the UI controller, security is only enabled for entry control devices, right??