Cannot include or exclude new devices

giantpopples · August 23, 2018, 3:06pm

Hello,

I am using openhab 2.4 with zwave binding 2.4.0.201808191228 with an everspring zwave+ dongle.
All my already included devices works fine but I can’t seem to include new devices, exclusion doesn’t seem to do anything either.

I have tried with 3 devices, none pair with openzwave, but works fine with a Vera3, so the device are working (I have since excluded them from the Vera, really quickly).

Here is the debug log from the inclusion process:

2018-08-23 16:47:29.262 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeDone

2018-08-23 16:47:29.265 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion

2018-08-23 16:47:29.267 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done

2018-08-23 16:47:29.268 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Starting ZWave inclusion scan for zwave:serial_zstick:512

2018-08-23 16:47:29.271 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery completed

2018-08-23 16:47:29.274 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery could not resolve to a thingType! Manufacturer data not known.

2018-08-23 16:47:29.284 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery completed

2018-08-23 16:47:29.285 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery resolved to thingType zwave:fibaro_fgd212_00_000

2018-08-23 16:47:29.296 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery completed

2018-08-23 16:47:29.298 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery could not resolve to a thingType! Manufacturer data not known.

2018-08-23 16:47:29.307 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery completed

2018-08-23 16:47:29.308 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery resolved to thingType zwave:benext_tagreader_00_000

2018-08-23 16:47:29.316 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed

2018-08-23 16:47:29.317 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery resolved to thingType zwave:fibaro_fgsd002_00_000

2018-08-23 16:47:29.326 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery completed

2018-08-23 16:47:29.327 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery resolved to thingType zwave:fibaro_fgfs101_03_002

2018-08-23 16:47:29.336 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery completed

2018-08-23 16:47:29.337 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery could not resolve to a thingType! Manufacturer data not known.

2018-08-23 16:47:29.346 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 19: Device discovery completed

2018-08-23 16:47:29.347 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 19: Device discovery could not resolve to a thingType! Manufacturer data not known.

2018-08-23 16:47:29.356 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 21: Device discovery completed

2018-08-23 16:47:29.357 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 21: Device discovery could not resolve to a thingType! Manufacturer data not known.

2018-08-23 16:47:29.366 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 22: Device discovery completed

2018-08-23 16:47:29.367 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 22: Device discovery resolved to thingType zwave:shenzhen_powerplug_00_000

2018-08-23 16:47:29.377 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 23: Device discovery completed

2018-08-23 16:47:29.378 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 23: Device discovery could not resolve to a thingType! Manufacturer data not known.

2018-08-23 16:47:29.386 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 1

2018-08-23 16:47:29.388 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.

2018-08-23 16:47:29.388 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion

2018-08-23 16:47:29.389 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.

2018-08-23 16:47:29.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2018-08-23 16:47:29.391 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 E5 D4 

2018-08-23 16:47:29.392 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 E5 D4 

2018-08-23 16:47:29.393 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2018-08-23 16:47:29.393 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2018-08-23 16:47:29.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2626: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 229

2018-08-23 16:47:29.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-08-23 16:47:29.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-08-23 16:47:29.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-08-23 16:47:29.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2626: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 229

2018-08-23 16:47:29.395 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A E5 23 00 00 74 

2018-08-23 16:47:29.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2018-08-23 16:47:29.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2018-08-23 16:47:29.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=35, callback=229, payload=E5 23 00 00 

2018-08-23 16:47:29.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

**2018-08-23 16:47:29.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=35, callback=229, payload=E5 23 00 00** 

2018-08-23 16:47:29.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=35, callback=229, payload=E5 23 00 00

2018-08-23 16:47:29.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2626: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 229

2018-08-23 16:47:29.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2018-08-23 16:47:29.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2626: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 229

2018-08-23 16:47:29.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2626: (Callback 229)

2018-08-23 16:47:29.400 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2018-08-23 16:47:29.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2626: callback 229

2018-08-23 16:47:29.401 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=35, callback=229, payload=E5 23 00 00 

2018-08-23 16:47:29.402 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Unknown request (35).

2018-08-23 16:47:29.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2626: Advanced to DONE

2018-08-23 16:47:29.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 9ms

2018-08-23 16:47:29.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2626: Transaction completed

2018-08-23 16:47:29.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2626 DONE

2018-08-23 16:47:29.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2018-08-23 16:47:29.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2018-08-23 16:47:50.981 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised

At the beginning some previously added device on battery or not currently powered are discovered from the controller.

I think the pairing message is received but then nothing is done with it, the log comes from trying to add a Fibaro Smoke sensor (I have one working in my setup so I know the device can be recognized).

How can I troubleshoot this issue ?

Thank you very much for your help

5iver · August 23, 2018, 3:44pm

Did you download a compiled jar or did you build the zwave binding yourself?

giantpopples · August 23, 2018, 4:52pm

I download it here, on this topic https://community.openhab.org/t/oh2-z-wave-refactoring-and-testing-and-security/21653/3813

It seems that Chris Jackson have posted a new version today, I’ll update it but when I tried on another computer with a fresh openhab install and I couldn’t include the device but I did not saved the log

giantpopples · August 24, 2018, 9:24pm

After using the z-wave PC Controller software, my zwave stick was marked as secondary controller which is weird since I have another secondary controller in the network.

I have decided to hard reset the controller and now everything is working, I had to include back all my devices but everything worked as expecting and pretty fast