Fibaro FGD212 stopps working on OH3.2, working fine on 2.4

pls68 · January 31, 2022, 5:54pm

I am starting to migrate from 2.4 to 3.2.
My FGD212 (node47, item name l_gallery_Stars) throws this error on OH 3.2 startup

2022-01-31 18:18:28.055[ERROR][alization.ZWaveNodeInitStageAdvancer] - NODE 47: Error in initialization thread
java.lang.NullPointerException: null
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doStaticStages(ZWaveNodeInitStageAdvancer.java:737) ~[bundleFile:?]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:213) [bundleFile:?]

The dimmer is not responding to any commands, although the log suggests the commands are being processed.

2022-01-31 18:29:44.500 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'l_gallery_Stars' received command 60
2022-01-31 18:29:44.505 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'l_gallery_Stars' predicted to become 60
2022-01-31 18:29:44.514 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'gLights_Gallery' changed from OFF to ON through l_gallery_Stars
2022-01-31 18:29:44.515 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'l_gallery_Stars' changed from 0 to 60

In the UI the device seems to be stuck at “Node initialising: UPDATE_DATABASE”
As soon as I revert back to 2.4 the dimmer works as expected.
Any thoughts? Thank you!

edit:
forgot to mention, same behaviour on 3.2 binding and 3.3 milestone zwave binding

domofl · January 31, 2022, 6:16pm

I have multiple FGD212 working in 3.2. So its not 3.2. I guess its the upgrading process, maybe some misconfiguration.

See also: My Z-Wave is borked

pls68 · January 31, 2022, 7:05pm

good to know your dimmers are working. I did have a quick look at the configuration, nothing seems to be obviously amiss.
I also read up on the thread you mention, thank you.
I wonder what keeps the device from getting past UPDATE DATABASE.

chris · January 31, 2022, 7:24pm

Probably this is due to the exception. We’d need to see a debug log to see what is causing the exception - please try to provide this if you can (see the binding docs for setting this up).

anon71759204 · February 1, 2022, 3:04am

Not necessarily - there are two entries for the FDG212 in the Z-Wave database:

domofl · February 1, 2022, 5:05pm

true, but unlikely. Just for reference mine have FW 3.5

pls68 · February 1, 2022, 7:36pm

Mine is FW 3.4

@chris
I restarted openhab on DEBUG loglevel for the zwave binding.
Please find the log attached.

This seems to be moment when the binding throws an error

2022-02-01 20:03:41.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 47: Application Command Request (ALIVE:VERSION)
2022-02-01 20:03:41.381 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 47: Incoming command class COMMAND_CLASS_VERSION, endpoint 0
2022-02-01 20:03:41.381 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 47: SECURITY NOT required on COMMAND_CLASS_VERSION
2022-02-01 20:03:41.382 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 47: Received COMMAND_CLASS_VERSION V2 VERSION_COMMAND_CLASS_REPORT
2022-02-01 20:03:41.382 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 47: Process Version Command Class Report
2022-02-01 20:03:41.382 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 47: Requested Command Class = COMMAND_CLASS_MANUFACTURER_SPECIFIC, Version = 2
2022-02-01 20:03:41.383 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 47: Version = 1, version set to maximum supported by the binding. Enabling extra functionality.
2022-02-01 20:03:41.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 47: Commands processed 1.
2022-02-01 20:03:41.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 47: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@a292a.
2022-02-01 20:03:41.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 47: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@a292a.
2022-02-01 20:03:41.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 47: notifyTransactionResponse TID:186 DONE
2022-02-01 20:03:41.385 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-02-01 20:03:41.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 186: Transaction event listener: DONE: DONE -> 
2022-02-01 20:03:41.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-02-01 20:03:41.386 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7acea
2022-02-01 20:03:41.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-02-01 20:03:41.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-02-01 20:03:41.386 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node Init transaction completed with response COMPLETE
2022-02-01 20:03:41.386 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer - advancing to ENDPOINTS
2022-02-01 20:03:41.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-02-01 20:03:41.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2022-02-01 20:03:41.387 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 1C 07 60 0D 01 02 32 01 00 25 20 A1 
2022-02-01 20:03:41.388 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: ENDPOINTS - MultiInstance not supported.
2022-02-01 20:03:41.388 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 28: Sending REQUEST Message = 01 0E 00 13 1C 07 60 0D 01 02 32 01 00 25 20 A1 
2022-02-01 20:03:41.388 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer - advancing to UPDATE_DATABASE
2022-02-01 20:03:41.389 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2022-02-01 20:03:41.390 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE
2022-02-01 20:03:41.391 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-02-01 20:03:41.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-02-01 20:03:41.395 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2022-02-01 20:03:41.398 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - check properties
2022-02-01 20:03:41.399 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property commandClass:COMMAND_CLASS_ASSOCIATION_GRP_INFO == ccRemove
2022-02-01 20:03:41.399 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - optionmap {ccRemove=}
2022-02-01 20:03:41.400 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - removing COMMAND_CLASS_ASSOCIATION_GRP_INFO
2022-02-01 20:03:41.400 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property versionMax == 3.4
2022-02-01 20:03:41.400 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property modelId == FGD212
2022-02-01 20:03:41.401 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property vendor == Fibargroup
2022-02-01 20:03:41.401 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property defaultAssociations == 1
2022-02-01 20:03:41.402 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property manufacturerId == 010F
2022-02-01 20:03:41.402 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property manufacturerRef == 0102:1000,0102:2000,0102:3000,0102:4000
2022-02-01 20:03:41.402 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property dbReference == 133
2022-02-01 20:03:41.402 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - property commandClass:COMMAND_CLASS_ASSOCIATION_GRP_INFO:2 == ccRemove
2022-02-01 20:03:41.403 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Node advancer: UPDATE_DATABASE - optionmap {ccRemove=}
2022-02-01 20:03:41.409 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-02-01 20:03:41.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 187: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 32
2022-02-01 20:03:41.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-02-01 20:03:41.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 187: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 32
2022-02-01 20:03:41.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-02-01 20:03:41.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-02-01 20:03:41.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-02-01 20:03:41.403 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 47: Error in initialization thread
java.lang.NullPointerException: null
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doStaticStages(ZWaveNodeInitStageAdvancer.java:737) ~[bundleFile:?]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:213) [bundleFile:?]

what also looks fishy is this

NODE 47: SECURITY_ERR Failed authentication! [97 B4 27 2A C6 23 34 1C ]<>[73 11 F9 05 80 42 D8 4F ]

Thank you for looking into this!
openhab.zip.log (543.0 KB)
had to add .log to the zipped log file to be able to upload

pls68 · February 25, 2022, 3:23pm

@chris may I ask If you had the chance to take a look at the log yet?

chris · February 25, 2022, 6:57pm

Sorry - I was away on holiday for a couple of weeks when you sent this and had no internet, and I missed this when I returned.

The issue is that the device reports that it doesn’t support multiple endpoints (or more accurately it doesn’t report the appropriate command classes in the NIF). Then when it comes to remove some classes that have been problematic in the past, this fails as endpoint 2 doesn’t exist.

I’m not sure why this would have changed - the device database hasn’t changed for 2 years! I can add a fix around this issue to prevent the exception, but probably there is another problem as this device should have 2 endpoints.

pls68 · February 25, 2022, 7:50pm

Thank you Chris for looking into this.
Strange indeed that this is happening.
I’d be happy to test any fix.
Just let me know.

chris · February 25, 2022, 7:51pm

It should be in the binding in the next day or so (tomorrow EU time should be fine) as I will merge this shortly.

chris · February 25, 2022, 7:52pm

It’s now merged…

pls68 · February 25, 2022, 7:54pm

wow, that was fast! Thank you!
When will this be included in the next build?

chris · February 25, 2022, 7:56pm

As above - it should be part of the nightly build, so it should be in tomorrows snapshot.

pls68 · February 25, 2022, 8:03pm

Sorry, I only read your second post

pls68 · February 27, 2022, 7:47am

@chris I gave the latest snapshot a try.
Alas, with that version my razberry zwave controller will not come online.
Switching back to 3.2. binding it comes online instantly.
I am having a hard time to believe that your fix has something to do with this.
I am at a loss as to what could be causing this.
Haven’t had the time to do a proper openhab restart with the zwave binding on debug log level yet. Will do so as soon as I find the time and report back.

chris · February 27, 2022, 8:17am

I suspect if you are using OH3.2 then you can’t currently use the OH3.3 snapshot due to some breaking changes. I see some PRs that will reverse this change, so in the coming days it might again be possible to do this.

system · April 10, 2022, 12:17am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.