Z-Wave Issues discovering devices with Aeotec Z-Stick 10 Pro

msexton187 · March 6, 2025, 2:26am

I’m trying to replace an old Z-Stick 5 that is failing with a Z-Stick 10. Openhab 4.3.3 is unable to discover devices that I’m trying to pair. I’m getting the warnings below.

2025-03-05 19:47:40.421 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 1: Device discovery could not resolve to a thingType! Manufacturer data not known.
2025-03-05 19:47:40.426 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.

These devices are old Z-wave devices that discover just fine with my my Z-Stick 5. I’m curious if anyone else has got the Z-Stick 10 to work with Openhab. Any help would be appreciated. Below are the Full Z-wave logs. I tried a couple of times during the log period below. The first try the log level was set for DEBUG and the second try it was set for TRACE.

2025-03-05 19:52:33.941 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:64d7c7f7c4
2025-03-05 19:52:33.942 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeDone
2025-03-05 19:52:33.942 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2025-03-05 19:52:33.942 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2025-03-05 19:52:33.942 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:64d7c7f7c4
2025-03-05 19:52:33.942 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2025-03-05 19:52:33.943 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-03-05 19:52:33.943 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2025-03-05 19:52:33.944 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.
2025-03-05 19:52:33.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 24 to queue - size 1
2025-03-05 19:52:33.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:33.944 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 09 38 
2025-03-05 19:52:33.945 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 09 38 
2025-03-05 19:52:33.958 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:52:33.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 24: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 9
2025-03-05 19:52:33.958 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:5767f857b9
2025-03-05 19:52:33.959 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2025-03-05 19:52:33.959 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:5767f857b9
2025-03-05 19:52:33.959 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2025-03-05 19:52:33.959 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-03-05 19:52:33.960 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2025-03-05 19:52:33.960 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2025-03-05 19:52:33.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 25 to queue - size 1
2025-03-05 19:52:33.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:33.960 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 0A 7B 
2025-03-05 19:52:33.961 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 0A 7B 
2025-03-05 19:52:33.963 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:52:33.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:33.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:33.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2025-03-05 19:52:33.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:52:33.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:33.966 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 0A 07 00 00 00 B0 
2025-03-05 19:52:33.970 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:52:33.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 10
2025-03-05 19:52:33.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:33.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=10, payload=0A 07 00 00 00 
2025-03-05 19:52:33.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=10, payload=0A 07 00 00 00 
2025-03-05 19:52:33.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 10
2025-03-05 19:52:33.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:52:33.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 10
2025-03-05 19:52:33.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 25: (Callback 10)
2025-03-05 19:52:33.974 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:52:33.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 25: callback 10
2025-03-05 19:52:33.974 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=10, payload=0A 07 00 00 00 
2025-03-05 19:52:33.974 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2025-03-05 19:52:33.974 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeFail
2025-03-05 19:52:33.974 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:52:33.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 26 to queue - size 1
2025-03-05 19:52:33.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:33.975 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 25: Transaction CANCELLED
2025-03-05 19:52:33.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 2 attempts left!
2025-03-05 19:52:33.975 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 25: Transaction RESET with 2 retries remaining.
2025-03-05 19:52:33.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 25 to queue - size 2
2025-03-05 19:52:33.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:33.975 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 0B 7A 
2025-03-05 19:52:33.975 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 0B 7A 
2025-03-05 19:52:33.978 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:52:33.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:33.980 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 0B 07 00 00 00 B1 
2025-03-05 19:52:33.986 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:52:33.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 11
2025-03-05 19:52:33.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 25: Transaction not completed
2025-03-05 19:52:33.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:33.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 11
2025-03-05 19:52:33.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:52:33.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:33.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:33.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=11, payload=0B 07 00 00 00 
2025-03-05 19:52:33.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=11, payload=0B 07 00 00 00 
2025-03-05 19:52:33.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 11
2025-03-05 19:52:33.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:52:33.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 11
2025-03-05 19:52:33.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 25: (Callback 11)
2025-03-05 19:52:33.990 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:52:33.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 25: callback 11
2025-03-05 19:52:33.990 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=11, payload=0B 07 00 00 00 
2025-03-05 19:52:33.990 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2025-03-05 19:52:33.990 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeFail
2025-03-05 19:52:33.990 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:52:33.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Transaction already in queue - removed original
2025-03-05 19:52:33.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 27 to queue - size 1
2025-03-05 19:52:33.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:33.991 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 25: Transaction CANCELLED
2025-03-05 19:52:33.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 1 attempts left!
2025-03-05 19:52:33.991 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 25: Transaction RESET with 1 retries remaining.
2025-03-05 19:52:33.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 25 to queue - size 2
2025-03-05 19:52:33.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:33.991 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 0C 7D 
2025-03-05 19:52:33.992 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 0C 7D 
2025-03-05 19:52:33.994 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:52:33.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:33.996 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 0C 07 00 00 00 B6 
2025-03-05 19:52:34.002 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:52:34.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 12
2025-03-05 19:52:34.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 25: Transaction not completed
2025-03-05 19:52:34.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:34.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 12
2025-03-05 19:52:34.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:52:34.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:34.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:34.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=12, payload=0C 07 00 00 00 
2025-03-05 19:52:34.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=12, payload=0C 07 00 00 00 
2025-03-05 19:52:34.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 12
2025-03-05 19:52:34.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:52:34.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 25: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 12
2025-03-05 19:52:34.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 25: (Callback 12)
2025-03-05 19:52:34.006 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:52:34.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 25: callback 12
2025-03-05 19:52:34.006 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=12, payload=0C 07 00 00 00 
2025-03-05 19:52:34.006 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2025-03-05 19:52:34.006 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeFail
2025-03-05 19:52:34.006 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:52:34.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Transaction already in queue - removed original
2025-03-05 19:52:34.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 28 to queue - size 1
2025-03-05 19:52:34.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:34.007 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 25: Transaction CANCELLED
2025-03-05 19:52:34.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Retry count exceeded. Discarding message: TID 25: [CANCELLED] priority=Controller, requiresResponse=true, callback: 12
2025-03-05 19:52:34.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 25: Transaction completed
2025-03-05 19:52:34.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:25 CANCELLED
2025-03-05 19:52:34.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:34.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:34.008 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 0D B8 
2025-03-05 19:52:34.008 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 0D B8 
2025-03-05 19:52:34.010 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:52:34.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:34.013 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 0D 06 00 00 00 B6 
2025-03-05 19:52:34.018 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:52:34.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 28: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 13
2025-03-05 19:52:34.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:34.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 28: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 13
2025-03-05 19:52:34.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:52:34.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:34.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:34.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=13, payload=0D 06 00 00 00 
2025-03-05 19:52:34.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=13, payload=0D 06 00 00 00 
2025-03-05 19:52:34.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 28: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 13
2025-03-05 19:52:34.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:52:34.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 28: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 13
2025-03-05 19:52:34.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 28: (Callback 13)
2025-03-05 19:52:34.022 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:52:34.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 28: callback 13
2025-03-05 19:52:34.022 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=13, payload=0D 06 00 00 00 
2025-03-05 19:52:34.023 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2025-03-05 19:52:34.023 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2025-03-05 19:52:34.023 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:52:34.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 29 to queue - size 1
2025-03-05 19:52:34.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:34.024 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2025-03-05 19:52:34.024 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2025-03-05 19:52:34.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 28: Advanced to DONE
2025-03-05 19:52:34.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 6ms
2025-03-05 19:52:34.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 28: Transaction completed
2025-03-05 19:52:34.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:28 DONE
2025-03-05 19:52:34.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:34.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:34.025 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2025-03-05 19:52:34.025 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2025-03-05 19:52:34.027 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:52:34.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:34.039 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:52:34.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 29: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2025-03-05 19:52:34.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:52:34.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 29: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2025-03-05 19:52:34.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:52:34.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:52:34.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:52:34.451 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2025-03-05 19:52:35.970 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 1: Device discovery completed
2025-03-05 19:52:35.973 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 1: Device discovery could not resolve to a thingType! Manufacturer data not known.
2025-03-05 19:52:35.974 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2025-03-05 19:52:35.977 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.
2025-03-05 19:52:38.959 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 24: Timeout at state WAIT_REQUEST. 3 retries remaining.
2025-03-05 19:52:38.959 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 24: Transaction is current transaction, so clearing!!!!!
2025-03-05 19:52:38.959 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24: Transaction CANCELLED
2025-03-05 19:52:38.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:24 CANCELLED
2025-03-05 19:52:38.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:52:39.040 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 29: Timeout at state WAIT_REQUEST. 3 retries remaining.
2025-03-05 19:52:39.040 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 29: Transaction is current transaction, so clearing!!!!!
2025-03-05 19:52:39.040 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 29: Transaction CANCELLED
2025-03-05 19:52:39.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:29 CANCELLED
2025-03-05 19:52:39.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:53:33.942 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:64d7c7f7c4
2025-03-05 19:53:33.943 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeSent
2025-03-05 19:53:33.943 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:53:33.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 30 to queue - size 1
2025-03-05 19:53:33.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:53:33.943 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 0F BA 
2025-03-05 19:53:33.943 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 0F BA 
2025-03-05 19:53:33.954 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:53:33.954 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 30: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 15
2025-03-05 19:53:33.959 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:5767f857b9
2025-03-05 19:53:33.959 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2025-03-05 19:53:38.954 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 30: Timeout at state WAIT_REQUEST. 3 retries remaining.
2025-03-05 19:53:38.954 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 30: Transaction is current transaction, so clearing!!!!!
2025-03-05 19:53:38.954 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 30: Transaction CANCELLED
2025-03-05 19:53:38.954 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:30 CANCELLED
2025-03-05 19:53:38.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:53:48.954 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion timer at IncludeDone
2025-03-05 19:55:12.503 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2025-03-05 19:58:04.409 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:64d7c7f7c4
2025-03-05 19:58:04.410 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeDone
2025-03-05 19:58:04.410 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2025-03-05 19:58:04.410 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2025-03-05 19:58:04.410 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:64d7c7f7c4
2025-03-05 19:58:04.410 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2025-03-05 19:58:04.410 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-03-05 19:58:04.411 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2025-03-05 19:58:04.411 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.
2025-03-05 19:58:04.411 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 31 to queue - size 1
2025-03-05 19:58:04.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:58:04.412 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2025-03-05 19:58:04.412 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = AddNodeToNetwork (0x4a), type = Request
2025-03-05 19:58:04.412 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 33
2025-03-05 19:58:04.412 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 10 21 
2025-03-05 19:58:04.412 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 10 21 
2025-03-05 19:58:04.422 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:58:04.422 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 31: Transaction Start type AddNodeToNetwork 
2025-03-05 19:58:04.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 31: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 16
2025-03-05 19:58:04.422 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2025-03-05 19:58:04.422 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2025-03-05 19:58:04.422 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2025-03-05 19:58:04.423 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.423 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 31: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 16
2025-03-05 19:58:04.423 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.423 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.423 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:5767f857b9
2025-03-05 19:58:04.424 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2025-03-05 19:58:04.424 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:5767f857b9
2025-03-05 19:58:04.424 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2025-03-05 19:58:04.424 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-03-05 19:58:04.424 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2025-03-05 19:58:04.425 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2025-03-05 19:58:04.425 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 32 to queue - size 1
2025-03-05 19:58:04.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:58:04.425 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2025-03-05 19:58:04.425 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = AddNodeToNetwork (0x4a), type = Request
2025-03-05 19:58:04.425 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 96
2025-03-05 19:58:04.425 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 11 60 
2025-03-05 19:58:04.426 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 11 60 
2025-03-05 19:58:04.428 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:58:04.428 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2025-03-05 19:58:04.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2025-03-05 19:58:04.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:58:04.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.430 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2025-03-05 19:58:04.430 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 11 07 00 00 00 AB 
2025-03-05 19:58:04.430 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 4A 11 07 00 00 00 AB 
2025-03-05 19:58:04.430 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -85
2025-03-05 19:58:04.430 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2025-03-05 19:58:04.431 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 7: Message payload = 11 07 00 00 00 
2025-03-05 19:58:04.431 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2025-03-05 19:58:04.435 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:58:04.435 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction Start type AddNodeToNetwork 
2025-03-05 19:58:04.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 17
2025-03-05 19:58:04.435 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2025-03-05 19:58:04.435 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2025-03-05 19:58:04.435 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 17
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.436 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.438 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=17, payload=11 07 00 00 00 
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=17, payload=11 07 00 00 00 
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 17
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 17
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 32: (Callback 17)
2025-03-05 19:58:04.438 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:58:04.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 32: callback 17
2025-03-05 19:58:04.438 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=17, payload=11 07 00 00 00 
2025-03-05 19:58:04.438 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2025-03-05 19:58:04.439 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2025-03-05 19:58:04.439 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2025-03-05 19:58:04.439 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeFail
2025-03-05 19:58:04.439 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:58:04.439 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 33 to queue - size 1
2025-03-05 19:58:04.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.439 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.439 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.439 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4996ms
2025-03-05 19:58:04.439 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction CANCELLED
2025-03-05 19:58:04.439 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance ST: CANCELLED
2025-03-05 19:58:04.439 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance WT: null
2025-03-05 19:58:04.439 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance RX: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=17, payload=11 07 00 00 00 
2025-03-05 19:58:04.440 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance TO: CANCELLED
2025-03-05 19:58:04.440 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2025-03-05 19:58:04.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 2 attempts left!
2025-03-05 19:58:04.440 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction RESET with 2 retries remaining.
2025-03-05 19:58:04.440 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 32 to queue - size 2
2025-03-05 19:58:04.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:58:04.440 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2025-03-05 19:58:04.440 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = AddNodeToNetwork (0x4a), type = Request
2025-03-05 19:58:04.440 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 99
2025-03-05 19:58:04.440 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 12 63 
2025-03-05 19:58:04.440 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 12 63 
2025-03-05 19:58:04.443 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:58:04.443 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2025-03-05 19:58:04.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.445 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2025-03-05 19:58:04.445 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 12 07 00 00 00 A8 
2025-03-05 19:58:04.445 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 4A 12 07 00 00 00 A8 
2025-03-05 19:58:04.445 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -88
2025-03-05 19:58:04.445 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2025-03-05 19:58:04.445 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 7: Message payload = 12 07 00 00 00 
2025-03-05 19:58:04.445 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2025-03-05 19:58:04.451 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:58:04.451 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction Start type AddNodeToNetwork 
2025-03-05 19:58:04.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.451 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 32: Transaction not completed
2025-03-05 19:58:04.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
2025-03-05 19:58:04.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:58:04.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.452 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.452 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.452 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.454 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=18, payload=12 07 00 00 00 
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=18, payload=12 07 00 00 00 
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 32: (Callback 18)
2025-03-05 19:58:04.454 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:58:04.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 32: callback 18
2025-03-05 19:58:04.454 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=18, payload=12 07 00 00 00 
2025-03-05 19:58:04.454 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2025-03-05 19:58:04.455 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2025-03-05 19:58:04.455 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2025-03-05 19:58:04.455 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeFail
2025-03-05 19:58:04.455 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:58:04.455 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Transaction already in queue - removed original
2025-03-05 19:58:04.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 34 to queue - size 1
2025-03-05 19:58:04.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.455 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.455 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.455 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4996ms
2025-03-05 19:58:04.455 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction CANCELLED
2025-03-05 19:58:04.455 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance ST: CANCELLED
2025-03-05 19:58:04.456 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance WT: null
2025-03-05 19:58:04.456 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance RX: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=18, payload=12 07 00 00 00 
2025-03-05 19:58:04.456 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance TO: CANCELLED
2025-03-05 19:58:04.456 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2025-03-05 19:58:04.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 1 attempts left!
2025-03-05 19:58:04.456 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction RESET with 1 retries remaining.
2025-03-05 19:58:04.456 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 32 to queue - size 2
2025-03-05 19:58:04.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:58:04.456 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2025-03-05 19:58:04.456 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = AddNodeToNetwork (0x4a), type = Request
2025-03-05 19:58:04.456 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 98
2025-03-05 19:58:04.457 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 13 62 
2025-03-05 19:58:04.457 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 13 62 
2025-03-05 19:58:04.459 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:58:04.459 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2025-03-05 19:58:04.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.461 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2025-03-05 19:58:04.462 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 13 07 00 00 00 A9 
2025-03-05 19:58:04.462 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 4A 13 07 00 00 00 A9 
2025-03-05 19:58:04.462 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -87
2025-03-05 19:58:04.462 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2025-03-05 19:58:04.462 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 7: Message payload = 13 07 00 00 00 
2025-03-05 19:58:04.462 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2025-03-05 19:58:04.470 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:58:04.470 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction Start type AddNodeToNetwork 
2025-03-05 19:58:04.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.470 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 32: Transaction not completed
2025-03-05 19:58:04.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
2025-03-05 19:58:04.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:58:04.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.471 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.471 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.471 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.473 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=19, payload=13 07 00 00 00 
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=19, payload=13 07 00 00 00 
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 32: (Callback 19)
2025-03-05 19:58:04.473 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:58:04.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 32: callback 19
2025-03-05 19:58:04.474 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=19, payload=13 07 00 00 00 
2025-03-05 19:58:04.474 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2025-03-05 19:58:04.474 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2025-03-05 19:58:04.474 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2025-03-05 19:58:04.474 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeFail
2025-03-05 19:58:04.474 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:58:04.474 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Transaction already in queue - removed original
2025-03-05 19:58:04.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 35 to queue - size 1
2025-03-05 19:58:04.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.474 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.474 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.475 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4995ms
2025-03-05 19:58:04.475 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction CANCELLED
2025-03-05 19:58:04.475 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance ST: CANCELLED
2025-03-05 19:58:04.475 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance WT: null
2025-03-05 19:58:04.475 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance RX: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=19, payload=13 07 00 00 00 
2025-03-05 19:58:04.475 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 32: TransactionAdvance TO: CANCELLED
2025-03-05 19:58:04.475 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2025-03-05 19:58:04.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Retry count exceeded. Discarding message: TID 32: [CANCELLED] priority=Controller, requiresResponse=true, callback: 19
2025-03-05 19:58:04.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 32: Transaction completed
2025-03-05 19:58:04.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:32 CANCELLED
2025-03-05 19:58:04.476 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2025-03-05 19:58:04.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:58:04.476 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2025-03-05 19:58:04.476 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = AddNodeToNetwork (0x4a), type = Request
2025-03-05 19:58:04.476 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -95
2025-03-05 19:58:04.476 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 14 A1 
2025-03-05 19:58:04.476 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 14 A1 
2025-03-05 19:58:04.478 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:58:04.478 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2025-03-05 19:58:04.478 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.481 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2025-03-05 19:58:04.481 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 4A 14 06 00 00 00 AF 
2025-03-05 19:58:04.481 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 4A 14 06 00 00 00 AF 
2025-03-05 19:58:04.481 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -81
2025-03-05 19:58:04.481 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2025-03-05 19:58:04.481 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 6: Message payload = 14 06 00 00 00 
2025-03-05 19:58:04.481 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2025-03-05 19:58:04.488 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:58:04.488 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 35: Transaction Start type AddNodeToNetwork 
2025-03-05 19:58:04.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 35: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 35: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.488 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 35: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
2025-03-05 19:58:04.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:58:04.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.489 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.489 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.489 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:04.491 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=20, payload=14 06 00 00 00 
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=20, payload=14 06 00 00 00 
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 35: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 35: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 35: (Callback 20)
2025-03-05 19:58:04.491 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2025-03-05 19:58:04.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 35: callback 20
2025-03-05 19:58:04.491 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=20, payload=14 06 00 00 00 
2025-03-05 19:58:04.491 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2025-03-05 19:58:04.491 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2025-03-05 19:58:04.491 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2025-03-05 19:58:04.491 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2025-03-05 19:58:04.491 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2025-03-05 19:58:04.492 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
2025-03-05 19:58:04.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 36 to queue - size 1
2025-03-05 19:58:04.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.492 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.492 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.492 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4996ms
2025-03-05 19:58:04.492 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2025-03-05 19:58:04.492 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2025-03-05 19:58:04.492 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 35: TransactionAdvance ST: WAIT_REQUEST
2025-03-05 19:58:04.492 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 35: TransactionAdvance WT: null
2025-03-05 19:58:04.492 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 35: TransactionAdvance RX: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=20, payload=14 06 00 00 00 
2025-03-05 19:58:04.492 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 35: TransactionAdvance RQ: RREQ=true, RCLS=null
2025-03-05 19:58:04.492 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 35: TransactionAdvance TO: DONE
2025-03-05 19:58:04.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 35: Advanced to DONE
2025-03-05 19:58:04.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 4ms
2025-03-05 19:58:04.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 35: Transaction completed
2025-03-05 19:58:04.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:35 DONE
2025-03-05 19:58:04.493 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2025-03-05 19:58:04.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-03-05 19:58:04.493 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2025-03-05 19:58:04.493 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = AddNodeToNetwork (0x4a), type = Request
2025-03-05 19:58:04.493 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -75
2025-03-05 19:58:04.493 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2025-03-05 19:58:04.493 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2025-03-05 19:58:04.495 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-03-05 19:58:04.495 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2025-03-05 19:58:04.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.502 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-03-05 19:58:04.502 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 36: Transaction Start type AddNodeToNetwork 
2025-03-05 19:58:04.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 36: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 36: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.502 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 5000ms
2025-03-05 19:58:04.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-03-05 19:58:04.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 36: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2025-03-05 19:58:04.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-03-05 19:58:04.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-03-05 19:58:04.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-03-05 19:58:04.503 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2025-03-05 19:58:04.503 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2025-03-05 19:58:04.503 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 05 19:58:09 CST 2025 - 4999ms
2025-03-05 19:58:06.436 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 1: Device discovery completed

apella12 · March 6, 2025, 1:31pm

I haven’t seen this controller before. Could you run a debug with the controller deleted from the UI and then a manual readdition? I’m assuming there are no nodes on the network yet?

The reason is that there is at least one issue with the controllers shipped with the latest SDK. Want to eliminate that first.

Edit: Or just follow the guide (if SDK 7.21 or & 7.22) and see if that fixes the inclusion

msexton187 · March 7, 2025, 1:51am

Changing the number of bits via the procedure fixed the problem. I’m on SDK 7.22. Thanks for the quick response.

Marty