ZWave - discovery/scan not working (nothing shows up in inbox/logs)

Hello,

Am running OpenHab 3 on a Raspberry Pi using a fresh openhabian image with a ZWave.me UZB stick and trying to add a (any) zwave device to the controller. I am unable to discover any zwave devices (i.e., nothing shows up in the inbox and the log does not appear to me at least to see any devices during inclusion).

I have tried four or five different zwave devices (some brand new, some previously in a Wink zwave network), using the manufacturer’s inclusion process while I click the Scan button in the OpenHab UI. I believe I will see the zwave devices in the log during exclusion, but never during inclusion.

Below is my log from where I attempt to add an Aeotec ZW187 sensor, which is in the list of supported zwave devices for the binding. I have attempted low power inclusion mode, high power inclusion mode, and network inclusion mode, but the below log is with high power inclusion mode. I have updated the UZB firmware to the latest (using a different computer from the Raspberry Pi).

2021-02-13 09:02:32.678 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:9c22f7c4c9
2021-02-13 09:02:32.687 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2021-02-13 09:02:32.693 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:9c22f7c4c9
2021-02-13 09:02:32.700 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 1
2021-02-13 09:02:32.705 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2021-02-13 09:02:32.710 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2021-02-13 09:02:32.718 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.
2021-02-13 09:02:32.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 159 to queue - size 1
2021-02-13 09:02:32.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-02-13 09:02:32.741 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 89 B8 
2021-02-13 09:02:32.747 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 89 B8 
2021-02-13 09:02:32.754 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-02-13 09:02:32.755 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-02-13 09:02:32.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 159: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 137
2021-02-13 09:02:32.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-02-13 09:02:32.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-02-13 09:02:32.777 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 89 01 00 00 3A 
2021-02-13 09:02:32.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 159: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 137
2021-02-13 09:02:32.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-02-13 09:02:32.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=137, payload=89 01 00 00 
2021-02-13 09:02:32.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-02-13 09:02:32.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-02-13 09:02:32.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=137, payload=89 01 00 00 
2021-02-13 09:02:32.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 159: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 137
2021-02-13 09:02:32.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-02-13 09:02:32.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 159: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 137
2021-02-13 09:02:32.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 159: (Callback 137)
2021-02-13 09:02:32.818 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-02-13 09:02:32.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 159: callback 137
2021-02-13 09:02:32.825 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=137, payload=89 01 00 00 
2021-02-13 09:02:32.829 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2021-02-13 09:02:32.832 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2021-02-13 09:02:32.835 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 159: Transaction COMPLETED
2021-02-13 09:02:32.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 80ms
2021-02-13 09:02:32.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 159: Transaction completed
2021-02-13 09:02:32.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:159 DONE
2021-02-13 09:02:32.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-02-13 09:02:32.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-02-13 09:03:32.690 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:9c22f7c4c9
2021-02-13 09:03:32.694 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
2021-02-13 09:03:32.697 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2021-02-13 09:03:32.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 160 to queue - size 1
2021-02-13 09:03:32.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-02-13 09:03:32.707 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 8A 3F 
2021-02-13 09:03:32.711 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 8A 3F 
2021-02-13 09:03:32.714 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-02-13 09:03:32.715 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-02-13 09:03:32.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 160: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 138
2021-02-13 09:03:32.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-02-13 09:03:32.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-02-13 09:03:32.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 160: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 138
2021-02-13 09:03:32.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-02-13 09:03:32.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-02-13 09:03:32.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-02-13 09:03:32.867 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 8A 06 00 00 3E 
2021-02-13 09:03:32.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=138, payload=8A 06 00 00 
2021-02-13 09:03:32.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=138, payload=8A 06 00 00 
2021-02-13 09:03:32.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 160: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 138
2021-02-13 09:03:32.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-02-13 09:03:32.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 160: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 138
2021-02-13 09:03:32.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 160: (Callback 138)
2021-02-13 09:03:32.892 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-02-13 09:03:32.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 160: callback 138
2021-02-13 09:03:32.899 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=138, payload=8A 06 00 00 
2021-02-13 09:03:32.903 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2021-02-13 09:03:32.907 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
2021-02-13 09:03:32.910 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2021-02-13 09:03:32.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 161 to queue - size 1
2021-02-13 09:03:32.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-02-13 09:03:32.922 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2021-02-13 09:03:32.925 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2021-02-13 09:03:32.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 160: Advanced to DONE
2021-02-13 09:03:32.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 214ms
2021-02-13 09:03:32.934 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 160: Transaction completed
2021-02-13 09:03:32.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:160 DONE
2021-02-13 09:03:32.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-02-13 09:03:32.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-02-13 09:03:32.950 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2021-02-13 09:03:32.955 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2021-02-13 09:03:32.960 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-02-13 09:03:32.960 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-02-13 09:03:32.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 161: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2021-02-13 09:03:32.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-02-13 09:03:32.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-02-13 09:03:32.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 161: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2021-02-13 09:03:32.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-02-13 09:03:32.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-02-13 09:03:32.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-02-13 09:03:37.971 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 161: Timeout at state WAIT_REQUEST. 3 retries remaining.
2021-02-13 09:03:37.974 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 161: Transaction is current transaction, so clearing!!!!!
2021-02-13 09:03:37.977 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 161: Transaction CANCELLED
2021-02-13 09:03:37.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:161 CANCELLED
2021-02-13 09:03:37.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Thanks,
Prokhor

I am on mobile and cannot check the logs. Are your controller end devices the proper frequency for your region if the world?

Everything looks fine, but it looks like the controller is just not finding any devices. Normally when we see this sort of thing it is caused by either the controller not working, or the controller being for the wrong region (ie a different region than the devices). I would suggest to check that the controller and devices are compatible.

1 Like

Thanks @Bruce_Osborne and @chris, very helpful to know I was not missing a step in configuring. I was counting on the manufacturer saying US was the default. Just now I switched it to another region and back via the manufacturer’s linux script. Still no luck. But just before breaking down and buying a new zwave controller USB stick, I noticed Wink was back up and had the thought to try to use the manufacturer’s software to add the UZB to the Wink hub as a secondary controller then move it back over the OpenHAB. Tried it and it worked…a couple hours after I plugged it in, I finally see that elusive Inbox icon with stuff in it. :joy: