[SOLVED] [ZWAVE] Device not showing when Searching for Things

mjeshurun · September 14, 2019, 3:55pm

I bought two Lumi switchboxes types for my apartment.

switchbox with 2 lights + 2 blinds buttons.
switchbox with 4 lights on/off buttons.

With the help of @chris @Bruce_Osborne @sihui and @5iver I was able to include and recognize the 2+2 switchbox using OpenHAB 2.5.0 Snapshot.

However, I’m facing another problem as the Zwave Binding doesn’t recognize the 4lights switchbox as a node when I put it in Inclusion mode. It just doesn’t show up, so I can’t pair it with OpenHAB.

In order to negate the possibility of a faulty switchbox, I tried to add the 4lights switchbox in Domoticz. And, unlike OpenHAB, Domoticz was able to recognize and control the 4lights switchbox as a usable node.

Is there anything I can do to make OpenHAB find the 4lights switchbox as a node?

chris · September 14, 2019, 3:58pm

Can you describe what you mean by this? Do you mean it doesn’t show up in the inbox at all? This seems strange - if the device includes with other software then it should also at least include, and be found as a node on the network with openHAB.

mjeshurun · September 14, 2019, 3:59pm

Exactly. It doesn’t show up in OpenHAB’s Inbox.

chris · September 14, 2019, 4:00pm

Then I think it’s not included into the network - what exactly are you doing? This really has nothing to do with openHAB - the inclusion is between the controller, and the device.

mjeshurun · September 14, 2019, 4:04pm

In Paper UI, I choose Inbox.
In Inbox, I press Search for Things.
Then I press Z-Wave Binding.
OpenHAB then shows the message “Searching for Things”.
I put the switchbox into inclusion mode.
And then nothing happens. OpenHAB doesn’t “finds” the device, so I can’t add it.

chris · September 14, 2019, 4:05pm

What does the debug log show is happening?

mjeshurun · September 14, 2019, 4:07pm

Is the debug log located in userdata/logs/openhab.log ?

chris · September 14, 2019, 4:08pm

Yes - note that if you haven’t done so you’ll need to enable this (as per the binding docs).

mjeshurun · September 14, 2019, 4:13pm

Do I need to run the terminal command: [ log:set DEBUG org.openhab.binding.zwave ] within a specific folder?

Bruce_Osborne · September 14, 2019, 4:13pm

A crazy question. Is that device supposed to work in your Z-Wave region?
Devices from a different region would not be recognized.

chris · September 14, 2019, 4:13pm

You need to run it from the openHAB console.

chris · September 14, 2019, 4:14pm

He said it worked with other software, so I assume so?

mjeshurun · September 14, 2019, 4:15pm

Yes. It has the same local frequency as the other device we worked on and my ZWave USB Controller.
The weird thing is Domoticz is able to find, add and control the node with the same ZWave controller I’m using when I try to add it in OpenHAB.

mjeshurun · September 14, 2019, 4:17pm

Like this?

chris · September 14, 2019, 4:17pm

Yes.

mjeshurun · September 14, 2019, 4:19pm

Cool.
Should I now try to add the node and after it fails copy-past the log info here?

chris · September 14, 2019, 4:20pm

Yes, let’s see what that shows. You can also try using the tail command in the console, although if there’s a lot of logging from other bindings or the system, then it may get swamped…

mjeshurun · September 14, 2019, 4:21pm

My system is not really running yet. I’m still in the process of solving the recognition of both switchboxes.

mjeshurun · September 14, 2019, 4:27pm

This was captured by the log when I tried to search for a new thing:

2019-09-14 19:25:02.578 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:dea8ca97
2019-09-14 19:25:02.579 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2019-09-14 19:25:02.581 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:dea8ca97
2019-09-14 19:25:02.581 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2019-09-14 19:25:02.584 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-09-14 19:25:02.585 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2019-09-14 19:25:02.585 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2019-09-14 19:25:02.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 181 to queue - size 1
2019-09-14 19:25:02.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-14 19:25:02.586 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 AF DE 
2019-09-14 19:25:02.586 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 AF DE 
2019-09-14 19:25:02.587 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-14 19:25:02.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 181: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 175
2019-09-14 19:25:02.587 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-14 19:25:02.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-14 19:25:02.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-14 19:25:02.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 181: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 175
2019-09-14 19:25:02.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-14 19:25:02.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-14 19:25:02.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-14 19:25:02.590 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A AF 01 00 00 1C 
2019-09-14 19:25:02.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=175, payload=AF 01 00 00 
2019-09-14 19:25:02.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=175, payload=AF 01 00 00 
2019-09-14 19:25:02.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 181: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 175
2019-09-14 19:25:02.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-14 19:25:02.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 181: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 175
2019-09-14 19:25:02.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 181: (Callback 175)
2019-09-14 19:25:02.591 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-09-14 19:25:02.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 181: callback 175
2019-09-14 19:25:02.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=175, payload=AF 01 00 00 
2019-09-14 19:25:02.592 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2019-09-14 19:25:02.592 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2019-09-14 19:25:02.592 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 181: Transaction COMPLETED
2019-09-14 19:25:02.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 5ms
2019-09-14 19:25:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 181: Transaction completed
2019-09-14 19:25:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:181 DONE
2019-09-14 19:25:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-14 19:25:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-14 19:25:04.588 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2019-09-14 19:25:04.590 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery resolved to thingType zwave:hogar_lmsxzwcl_00_000
2019-09-14 19:25:08.871 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2019-09-14 19:26:02.589 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:dea8ca97
2019-09-14 19:26:02.590 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
2019-09-14 19:26:02.590 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-09-14 19:26:02.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 182 to queue - size 1
2019-09-14 19:26:02.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-14 19:26:02.591 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 B0 05 
2019-09-14 19:26:02.591 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 B0 05 
2019-09-14 19:26:02.591 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-14 19:26:02.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 182: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 176
2019-09-14 19:26:02.592 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-14 19:26:02.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-14 19:26:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-14 19:26:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 182: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 176
2019-09-14 19:26:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-14 19:26:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-14 19:26:02.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-14 19:26:02.643 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A B0 06 00 00 04 
2019-09-14 19:26:02.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=176, payload=B0 06 00 00 
2019-09-14 19:26:02.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=176, payload=B0 06 00 00 
2019-09-14 19:26:02.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 182: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 176
2019-09-14 19:26:02.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-14 19:26:02.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 182: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 176
2019-09-14 19:26:02.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 182: (Callback 176)
2019-09-14 19:26:02.645 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-09-14 19:26:02.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 182: callback 176
2019-09-14 19:26:02.645 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=176, payload=B0 06 00 00 
2019-09-14 19:26:02.645 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2019-09-14 19:26:02.645 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
2019-09-14 19:26:02.646 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-09-14 19:26:02.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 183 to queue - size 1
2019-09-14 19:26:02.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-14 19:26:02.646 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2019-09-14 19:26:02.646 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2019-09-14 19:26:02.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 182: Advanced to DONE
2019-09-14 19:26:02.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 54ms
2019-09-14 19:26:02.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 182: Transaction completed
2019-09-14 19:26:02.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:182 DONE
2019-09-14 19:26:02.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-14 19:26:02.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-14 19:26:02.647 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2019-09-14 19:26:02.647 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2019-09-14 19:26:02.647 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-14 19:26:02.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 183: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2019-09-14 19:26:02.648 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-14 19:26:02.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-14 19:26:02.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-14 19:26:02.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 183: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2019-09-14 19:26:02.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-14 19:26:02.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-14 19:26:02.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-14 19:26:07.653 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 183: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-09-14 19:26:07.654 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 183: Transaction is current transaction, so clearing!!!!!
2019-09-14 19:26:07.654 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 183: Transaction CANCELLED
2019-09-14 19:26:07.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:183 CANCELLED
2019-09-14 19:26:07.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

chris · September 14, 2019, 4:32pm

This didn’t find any new devices - I’m assuming you are also putting the device into inclusion mode?

What is node 3, and what device are you trying to include?