Z-wave Inclusion don't work on OH3.2

Fiftiz · June 26, 2022, 8:03am

Platform information:
Hardware: RPI 4 rev 1.5
OS: Openhabian 1.7.3
openHAB version: 3.2
Zwave stick : Aeotec Z-stick Gen5+ directly on USB3 port

hello, I have a problem with Z-wave.
Inclusion don’t work on OH3 and When I try the inclusion from Z-stick directly ,When I scan I have “unknow device” with all devices , same with device without battery, as fibaro wall plug v3.2.

Thank you very much

Here logs when I try inclusion on OH3 :

2022-06-26 09:52:26.957 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:5174f319b0
2022-06-26 09:52:26.960 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2022-06-26 09:52:26.963 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:5174f319b0
2022-06-26 09:52:26.966 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2022-06-26 09:52:26.969 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2022-06-26 09:52:26.972 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2022-06-26 09:52:26.975 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2022-06-26 09:52:26.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 32 to queue - size 1
2022-06-26 09:52:26.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-26 09:52:26.984 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 19 68 
2022-06-26 09:52:26.987 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 19 68 
2022-06-26 09:52:26.990 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-26 09:52:26.992 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-26 09:52:26.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 25
2022-06-26 09:52:26.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-26 09:52:26.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-26 09:52:27.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 25
2022-06-26 09:52:27.003 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 19 01 00 00 AA 
2022-06-26 09:52:27.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-26 09:52:27.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:27.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-26 09:52:27.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=25, payload=19 01 00 00 
2022-06-26 09:52:27.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=25, payload=19 01 00 00 
2022-06-26 09:52:27.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 25
2022-06-26 09:52:27.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-26 09:52:27.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 25
2022-06-26 09:52:27.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 32: (Callback 25)
2022-06-26 09:52:27.026 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-26 09:52:27.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 32: callback 25
2022-06-26 09:52:27.031 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=25, payload=19 01 00 00 
2022-06-26 09:52:27.033 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2022-06-26 09:52:27.035 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2022-06-26 09:52:27.038 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32: Transaction COMPLETED
2022-06-26 09:52:27.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 46ms
2022-06-26 09:52:27.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 32: Transaction completed
2022-06-26 09:52:27.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:32 DONE
2022-06-26 09:52:27.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:27.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-26 09:52:33.485 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 19 02 00 00 A9 
2022-06-26 09:52:33.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=25, payload=19 02 00 00 
2022-06-26 09:52:33.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=25, payload=19 02 00 00 
2022-06-26 09:52:33.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-26 09:52:33.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2022-06-26 09:52:33.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2022-06-26 09:52:33.502 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=25, payload=19 02 00 00 
2022-06-26 09:52:33.504 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2022-06-26 09:52:33.506 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:33.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-26 09:52:41.132 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 19 07 00 00 AC 
2022-06-26 09:52:41.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=25, payload=19 07 00 00 
2022-06-26 09:52:41.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=25, payload=19 07 00 00 
2022-06-26 09:52:41.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-26 09:52:41.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2022-06-26 09:52:41.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2022-06-26 09:52:41.151 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=25, payload=19 07 00 00 
2022-06-26 09:52:41.153 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2022-06-26 09:52:41.155 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeFail
2022-06-26 09:52:41.158 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2022-06-26 09:52:41.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 33 to queue - size 1
2022-06-26 09:52:41.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-26 09:52:41.165 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 1A AF 
2022-06-26 09:52:41.168 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 1A AF 
2022-06-26 09:52:41.171 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-26 09:52:41.172 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-26 09:52:41.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 33: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 26
2022-06-26 09:52:41.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:41.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-26 09:52:41.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-26 09:52:41.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-26 09:52:41.185 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 33: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 26
2022-06-26 09:52:41.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-26 09:52:41.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:41.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-26 09:52:41.226 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 1A 06 00 00 AE 
2022-06-26 09:52:41.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=26, payload=1A 06 00 00 
2022-06-26 09:52:41.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=26, payload=1A 06 00 00 
2022-06-26 09:52:41.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 33: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 26
2022-06-26 09:52:41.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-26 09:52:41.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 33: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 26
2022-06-26 09:52:41.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 33: (Callback 26)
2022-06-26 09:52:41.248 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-26 09:52:41.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 33: callback 26
2022-06-26 09:52:41.253 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=26, payload=1A 06 00 00 
2022-06-26 09:52:41.256 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2022-06-26 09:52:41.259 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2022-06-26 09:52:41.262 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2022-06-26 09:52:41.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 34 to queue - size 1
2022-06-26 09:52:41.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-26 09:52:41.270 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2022-06-26 09:52:41.273 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2022-06-26 09:52:41.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 33: Advanced to DONE
2022-06-26 09:52:41.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 105ms
2022-06-26 09:52:41.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 33: Transaction completed
2022-06-26 09:52:41.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:33 DONE
2022-06-26 09:52:41.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:41.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-26 09:52:41.296 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2022-06-26 09:52:41.299 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2022-06-26 09:52:41.302 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-26 09:52:41.303 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-26 09:52:41.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2022-06-26 09:52:41.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-26 09:52:41.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-26 09:52:41.312 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2022-06-26 09:52:41.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-26 09:52:41.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-26 09:52:41.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-26 09:52:46.307 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 34: Timeout at state WAIT_REQUEST. 3 retries remaining.
2022-06-26 09:52:46.310 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34: Transaction is current transaction, so clearing!!!!!
2022-06-26 09:52:46.312 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34: Transaction CANCELLED
2022-06-26 09:52:46.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:34 CANCELLED
2022-06-26 09:52:46.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-26 09:53:26.963 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:5174f319b0
2022-06-26 09:53:26.965 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do

stefan.hoehn · June 26, 2022, 9:10am

I am not sure exactly what the state of you system is not exactly what you are doing.

In general, the inclusion process is working from your logs. I pasted the logs to Z-Wave Log Viewer and it reveals

so the inclusion process itself works. It seems you are having problems with the nodes themselves.

So let’s start systematically:

Questions

is this the first time ever you include any node?
Did you setup the Zwave Serial controller (correctly)?
Do you see any zwave thing inbox?

Fiftiz · June 26, 2022, 9:59am

I tried, when I put a SSD (sata or Msata) on the USB port, Zwave stop work … I don’t understand why

On my other RPI rev 1.2 , all work

stefan.hoehn · June 26, 2022, 10:34am

The fact that you are mentioning you have connected an SSD to your system might lead to the assumption that you have an issue with your controller now (even though you actually receive something in the logs).

Do you mind answering my questions above, otherwise we cannot help you.

Fiftiz · June 26, 2022, 10:41am

I misspoke sorry . Without USB disk (so only the Z-stick on USB) , inclusions and devices work perfectly. So the problem is with USB because I tried with 2 disks (Msata USB disk and SSD USB disk) and when I put a disk, zwave no more work.

apella12 · June 26, 2022, 5:07pm

I don’t know how the Rpi4 is designed to handle USB traffic, but recognize that Zwave traffic is (at best) 100KB/sec and IIRC USB3 is up to 5 GB/sec or 50,000 faster. I have a Rpi4 with the SSD on the USB3 and the zstick on the USB2 and has been working fine for a couple of years. You could have other issues, but switching the zstick to the USB2 won’t slow anything down and might help.

Bob

robmac · June 26, 2022, 9:20pm

Could be too much power drain with those SSD or power supply not adequate.

Fiftiz · June 27, 2022, 5:11am

I have also 2 others PI4 (rev 1.1 and rev 1.2 ) with Zwave + SSD USB disk, and no problem… but this one (rev 1.5), I tried, 2 USB disk, 2 power supply, and it don’t work when I put USB disk… really I don’t understand

Fiftiz · June 28, 2022, 11:21am

Problem solved. need just to put an USB extension cable on the Zwave gen5+ , and now USB Msata work, there is interference with zwave when directly on USB 3.0.