Fibaro RGBW Controller 2 not using secure z-wave inclusion

Setup, Configuration and Use Installation
,
1

Just got a few Fibaro RGBW Controller 2 (FGRGBW-442) and I cannot get them to do a secure inclusion with my OpenHab 2.5.5. The Fibaros support both S0 and S2, but since OpenHab only supports S0 I am looking for them to use S0. I’m doing the inclusion from HABmin and keeping the Fibaro right next to the Aeotec z-stick (devices touching). I’ve also tried doing an exclusion and factory reset multiple times, and it still doesn’t do a secure inclusion. And, yes, the setting on the controller is secure inclusion for “All Devices”, not just “Entry Control Devices”.

Looking at the debug logs, it appears that it is attempting to do a secure inclusion, but I’m almost wondering if the Fibaro just doesn’t respond to it.

Thoughts of what to try next?

image

Here’s a snippet of the logs, but I’d be happy to share more details as needed:

2020-06-09 21:50:03.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 362: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2020-06-09 21:50:03.910 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-06-09 21:50:03.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-09 21:50:03.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-09 21:50:03.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 362: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2020-06-09 21:50:03.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-06-09 21:50:03.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-09 21:50:03.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-09 21:50:04.910 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: Node advancer - advancing to SECURITY_REPORT
2020-06-09 21:50:04.911 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 152: Updated networkKey
2020-06-09 21:50:04.911 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 152: setupNetworkKey useSchemeZero=false
2020-06-09 21:50:04.912 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: Performing secure inclusion.
2020-06-09 21:50:04.912 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: SECURITY_INC State=GET_SCHEME
2020-06-09 21:50:04.912 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: ZWaveCommandClassTransactionPayload - send to node
2020-06-09 21:50:04.913 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 152: SECURITY check internal
2020-06-09 21:50:04.913 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 152: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured
2020-06-09 21:50:04.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 152: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@757f07f4
2020-06-09 21:50:04.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 152: Adding to device queue
2020-06-09 21:50:04.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 152: Added 363 to queue - size 44
2020-06-09 21:50:04.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-09 21:50:08.910 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 362: Timeout at state WAIT_REQUEST. 3 retries remaining.
2020-06-09 21:50:08.911 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 362: Transaction is current transaction, so clearing!!!!!
2020-06-09 21:50:08.911 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 362: Transaction CANCELLED
2020-06-09 21:50:08.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:362 CANCELLED
2020-06-09 21:50:08.912 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-06-09 21:50:08.913 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 152: Sending REQUEST Message = 01 0A 00 13 98 03 98 04 00 25 CF 0B
2020-06-09 21:50:08.913 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-06-09 21:50:08.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 363: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 207
2020-06-09 21:50:08.914 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-06-09 21:50:08.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-09 21:50:08.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-09 21:50:08.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 363: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 207
2020-06-09 21:50:08.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-06-09 21:50:08.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-09 21:50:08.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-09 21:50:08.924 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2020-06-09 21:50:08.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2020-06-09 21:50:08.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2020-06-09 21:50:08.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 363: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 207
2020-06-09 21:50:08.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-06-09 21:50:08.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 363: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 207
2020-06-09 21:50:08.926 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2020-06-09 21:50:08.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 363: Advanced to WAIT_REQUEST
2020-06-09 21:50:08.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 152: TID 363: Transaction not completed
2020-06-09 21:50:08.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-09 21:50:08.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-09 21:50:08.941 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 CF 00 00 03 27
2020-06-09 21:50:08.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=207, payload=CF 00 00 03
2020-06-09 21:50:08.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=207, payload=CF 00 00 03
2020-06-09 21:50:08.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 363: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 207
2020-06-09 21:50:08.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-06-09 21:50:08.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 363: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 207
2020-06-09 21:50:08.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 363: (Callback 207)
2020-06-09 21:50:08.943 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-06-09 21:50:08.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 363: callback 207
2020-06-09 21:50:08.943 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=207, payload=CF 00 00 03
2020-06-09 21:50:08.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 363: Advanced to WAIT_DATA
2020-06-09 21:50:08.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 152: TID 363: Transaction not completed
2020-06-09 21:50:08.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2

Please can you provide the debug log so I can take a look at what is happening.

Thanks.

1 Like
3

Certainly. You can find it here. Look at node 152 as an example.

4

Just noticed this in the debug log:

2020-06-09 21:50:28.314 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: Node Init response (1) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@4440729b
2020-06-09 21:50:28.314 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: No data from device, but it was ACK'd. Possibly not supported? (Try 1)
2020-06-09 21:50:28.314 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-06-09 21:50:28.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 364: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2020-06-09 21:50:28.315 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: timed out after 23402059410 / 20000000000
2020-06-09 21:50:28.315 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-06-09 21:50:28.315 [INFO ] [alization.ZWaveNodeInitStageAdvancer] - NODE 152: SECURITY_INC State=FAILED, Reason=GET_SCHEME

In particular the following:

NODE 152: No data from device, but it was ACK'd. Possibly not supported? (Try 1)
5

I’m guessing a little, but I suspect that the device has already been included prior to this. The device is not responding to the security request which is indicative of this not being the first inclusion after a reset since the security inclusion will only work for 15 seconds after the inclusion.

1 Like
6

Yeah, I tend to agree with you. However, I was very careful to make sure to do an exclusion and factory reset (and have tried it multiple times) + pushing the “b-button” on the Fibaro 3 times within a second or two after starting the inclusion process in HABmin. I’m just wondering if maybe the Fibaro device isn’t responding in a timely manner?

Is the 15 seconds a protocol limitation, or potentially something that can be configured in OH to give the device a bit more time?

BTW: I’ve attempted the same thing on 3 different Fibaro units, and they all seem to behave the same way.

7

Sure - I appreciate this, but I’m not sure what else to suggest. I know sometimes people find the manual is wrong, and devices aren’t properly resetting. I doubt that’s the case here, but it’s how it looks from what I see in the log.

If you exclude/reset and include again, does it come up with a different node id?

If it. We see the ACK from the device almost immediately after the command was sent, so the device received the command but actively decided not to respond.

image
image1228×180 44.5 KB

It can’t be configured - it’s programmed into the device as required by the standards.

8

Thanks for the feedback and information @Chris. I’ve ordered another z-stick to have a “playground” to dig a bit further to avoid impacting the stable setup. I’ll see what I can find out and keep you posted.