FGK001 stops working after (re)inclusion with Z-Wave-DEV-Binding

I am struggling with the recent version of the Z-Wave-Dev-Branch (Dev-Snapshot 201710241752). I am using several FGK001 Fibaro Door/Window-Sensors which used to work well with the Dev-Snapshots.
I just reincluded one device with the current binding and since then it does not report the door status anymore to OH. The item (Channel sensor_door) does not get any updates any more. To be sure I reconfigured the device to indicate door status changes by LED and it does. I can also see in the logs that the device tries to send data to OH but it does not arrive where it should. Here is a typcial (reproducable) section of my Z-Wave debug logs (NODE 181):

2017-11-06 22:25:44.953 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 175: listening == false, frequentlyListening == false, awake == false
2017-11-06 22:25:44.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 175: Node not awake!
2017-11-06 22:25:44.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-11-06 22:25:44.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-11-06 22:25:45.609 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 04 00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 A6 
2017-11-06 22:25:45.610 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-11-06 22:25:45.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=181, callback=0, payload=00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-11-06 22:25:45.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=181, callback=0, payload=00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-11-06 22:25:45.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=181, callback=0, payload=00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-11-06 22:25:45.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-11-06 22:25:45.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 181: Application Command Request (ALIVE:DONE)
2017-11-06 22:25:45.610 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 181: resetResendCount initComplete=true isDead=false
2017-11-06 22:25:45.610 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 181: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-11-06 22:25:45.610 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 181: COMMAND_CLASS_MULTI_CHANNEL not found
2017-11-06 22:25:45.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-11-06 22:25:45.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-11-06 22:25:45.611 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 175: listening == false, frequentlyListening == false, awake == false
2017-11-06 22:25:45.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 175: Node not awake!
2017-11-06 22:25:45.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-11-06 22:25:45.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-11-06 22:25:46.556 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 A1 0A 32 02 21 34 00 00 00 00 00 00 65 
2017-11-06 22:25:46.556 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6

However the battery values are updated correctly (channel battery-level), but the main purpose of the device does not work anymore.
@chris Can you have a look, please?

Thank you!

I will look to merge the changes to solve the Qubino problems into the development version - I think that’s likely to solve this problem.

Thank you Chris!

Does this mean that using the “TEST”-DEV-Version would already solve the problem?

Yes - (I hope :wink: ). If you want to try that, let me know how it goes.

Ok, here we go. Do I need to reinclude the node?

No - just delete the XML and it should (I hope!) reinitialise the lifeline association group. If it doesn’t then please fire over a debug log…

I deleted the xml, woke up the device and a new xml was created. However, the triggering of the Door-Open-Event still does not arrive in OH, only in the logs (NODE 181):

2017-11-07 23:14:58.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 173: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4ff1a39e.
2017-11-07 23:14:58.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-11-07 23:14:58.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-11-07 23:14:58.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-11-07 23:14:58.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-11-07 23:14:58.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-11-07 23:14:58.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-11-07 23:14:59.399 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 04 00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 17 00 A7 
2017-11-07 23:14:59.400 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-11-07 23:14:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=181, callback=0, payload=00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 17 00 
2017-11-07 23:14:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=181, callback=0, payload=00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 17 00 
2017-11-07 23:14:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=181, callback=0, payload=00 B5 0D 60 0D 00 00 71 05 00 00 00 FF 06 17 00 
2017-11-07 23:14:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-11-07 23:14:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 181: Application Command Request (ALIVE:DONE)
2017-11-07 23:14:59.400 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 181: resetResendCount initComplete=true isDead=false
2017-11-07 23:14:59.400 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 181: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-11-07 23:14:59.400 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 181: COMMAND_CLASS_MULTI_CHANNEL not found
2017-11-07 23:14:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-11-07 23:14:59.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-11-07 23:14:59.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-11-07 23:14:59.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-11-07 23:15:02.917 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 33 03 20 03 FF 1E 
2017-11-07 23:15:02.918 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-11-07 23:15:02.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=0, payload=00 33 03 20 03 FF 
2017-11-07 23:15:02.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=0, payload=00 33 03 20 03 FF 
2017-11-07 23:15:02.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=51, callback=0, payload=00 33 03 20 03 FF 
2017-11-07 23:15:02.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-11-07 23:15:02.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Application Command Request (ALIVE:DONE)

Do you need the debug-log from the reinitialization-phase?

Yes please.

ok, here it is (NODE 181)

https://filebin.ca/3gWCDvldH6Mn

Thanks, but unfortunately this only starts toward the end of the initialisation - either it was a restart without deleting the XML, or the logs cycled maybe and the first part is in another log?

Here is more:

https://filebin.ca/3gWG99H4ibYP

It still doesn’t have the initialisation in it :frowning: .

Just to be sure that we talk about the same: I just deleted the node WHILE OH was running. Should I shutdown OH, then delete the XML and then restart OH with the new binding version?

If by “deleted the node” you mean deleted the XML file, then this won’t work - you need to do one of the following -:

  • Stop OH, delete the node, start OH
  • In the thing configuration, select the reinitialize node opton.

Ok, I tested now intensively the last different versions of the DEV binding in my test environment (same controller type, same FGK101 door sensor version, same OH2 snapshot version but only one node to speed up test cases) .
The finding: FGK101 works only if included in the network with network wide inclusion with DEV Snaphot version 20170918 or older. In this case the sensor reports the channel sensor_door correctly to the associated item. Even after updating the DEV Snaphot version to newer builds (without reincluding the device) the channel sensor_door still reports correctly.
However, if the FGK101 is included in the network with network wide inclusion with DEV Snaphot version 20171024 it does NOT report the channel sensor_door (only channel battery-level is still updated). Downgrading the DEV Snaphot version back to 20170918 does not help either. The sensor won’t report the channel sensor_door if included with the newer DEV version.
Conclusion: it is the binding version in the moment of inclusion which makes the difference (similar as it used to be with Fibaro double relay switch FGS223 or some Qubino devices).

Finally I also produced the debug log you are waiting for. It should include the (faulty) inclusion process with DEV Snaphot version 20171024 completely (NODE 4).

https://filebin.net/gsu0klusddpos8ez

I hope you can find anything in there. If you need some more logs from different scenarios please let me know.

Thanks for your work!

@chris: And two more (hopefully useful) files:

The xml generated by the DEV Snaphot version 20171024 which is NOT working (Node 181):

network_d763b7a3__node_181.xml (22.8 KB)

and here the xml generated by the DEV Snaphot version 20170918 which works perfectly (with all binding versions if inclusion took place with DEV Snaphot version 20170918) (NODE 182):

network_d763b7a3__node_182.xml (19.2 KB)

@chris : Did you have a chance to look into this?

@chris
I think I run into the same problem. I’m on OH 2.3 stable. I prepare for the migration to 2.4. For this I delete one sensor thing and added it again (no exclude/include). Now the sensor is not working as before. There must be a change in the database. Some of the channels are no longer there

Before and all working:

Contact DoorSensor42				"Fenster Wohnzimmer Links [MAP(de.map):%s]"			<contact>(gRestoreStateCO,gnuDoorSensor_OpenClose_Status,gswDoorSensor_OpenClose_Status,gswDoorSensor_OpenClose_Status_All){ channel="zwave:device:15a7a49f3a6:node42:sensor_door"}
Number DoorSensor42_Battery  			"Fenster Wohnzimmer Links [%d %%]"  				<battery>(gMonitorLastUpdateNU,gRestoreStateNU,gRRD4J,gBatterieLevelNU){ channel="zwave:device:15a7a49f3a6:node42:battery-level"}
Switch DoorSensor42_TamperAlarm			"Fenster Wohnzimmer Links Alarm [%s]"				<contact>(gRestoreStateSW){ channel="zwave:device:15a7a49f3a6:node42:alarm_general"}

Now only battery-level work as before. I played around a little bit and get the door/window magnet to work again, but this is now a switch and no longer a contact and has a different channel name.

Switch DoorSensor42_Binary			    "Fenster Wohnzimmer Links [%s]"				<contact>(gMAPDB){ channel="zwave:device:15a7a49f3a6:node42:sensor_binary"}

With tamper I got no success anymore.

Sensor is firmware version 2.5. XML attached. What should I do?node42.xml (10.2 KB)

This is the XML-file from another one which is still working. But this one was not deleted and readded, config was from z-wave binding version 2.0. maybe this help. node58.xml (9.9 KB)