FGS211 Zwave Item events not firing

[evans_jon (Jon Evans)]

Hi

I’m using the latest 2.5.0 docker snapshot (latest == from yesterday evening), although I had the same problem with 2.5.0.M1. I know this did work OK at one time (2.4.0 I think).

I have some Fibaro FGS211 single relay switches, and I’m finding that although they have the correct Controller Updates association, and the controller receives commands from the devices when the switches are operated manually, the item state is not updated.

Here’s some output captured when manually toggling a bedroom light on and off from its switch, followed by doing the same with the bathroom light. The bedroom light (NODE 82) is an FGS213 and the bathroom light (NODE 15) is an FGS211. I have three FGS211 in the house and they all exhibit the same problem.

I can operate the lights fine from openHAB, which would seem to indicate that the Item is correctly associated with the Thing.

I have tried deleting the Thing from openHAB (NB not removing it from the Z-wave network) and re-adding it, that didn’t fix it.

I thought the issue would be that the Controller Updates group wasn’t set, but it looks like that’s not the case given that the messages appear in the zwave log in real time as the switch is changed.

This is the command I run, so that the output from the various logs will interleave on screen:

tail -F /opt/openhab/userdata/logs/events.log /opt/openhab/userdata/logs/zwave.log

Here’s the output:

==> /opt/openhab/userdata/logs/zwave.log <==
27-Mar-2019 12:12:09.736 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 52 07 60 0D 01 01 25 03 FF 17
27-Mar-2019 12:12:09.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 07 60 0D 01 01 25 03 FF
27-Mar-2019 12:12:09.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 07 60 0D 01 01 25 03 FF
27-Mar-2019 12:12:09.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
27-Mar-2019 12:12:09.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Application Command Request (ALIVE:DONE)
27-Mar-2019 12:12:09.737 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: resetResendCount initComplete=true isDead=false
27-Mar-2019 12:12:09.738 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
27-Mar-2019 12:12:09.738 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 1
27-Mar-2019 12:12:09.738 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
27-Mar-2019 12:12:09.738 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 82: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
27-Mar-2019 12:12:09.738 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 82: Switch Binary report, value = 255
27-Mar-2019 12:12:09.738 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
27-Mar-2019 12:12:09.739 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_BINARY, value=255
27-Mar-2019 12:12:09.739 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Updating channel state zwave:device:521e1911:node82:switch_binary1 to ON [OnOffType]
27-Mar-2019 12:12:09.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Commands processed 1.
27-Mar-2019 12:12:09.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2235a15.
27-Mar-2019 12:12:09.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:09.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:09.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
27-Mar-2019 12:12:09.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

==> /opt/openhab/userdata/logs/events.log <==
2019-03-27 12:12:09.740 [vent.ItemStateChangedEvent] - Light_MasterBedroom_Ceiling changed from OFF to ON

==> /opt/openhab/userdata/logs/zwave.log <==
27-Mar-2019 12:12:11.858 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 12 00 04 00 52 0C 60 0D 01 01 32 02 21 32 01 08 00 00 F0
27-Mar-2019 12:12:11.858 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 0C 60 0D 01 01 32 02 21 32 01 08 00 00
27-Mar-2019 12:12:11.859 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 0C 60 0D 01 01 32 02 21 32 01 08 00 00
27-Mar-2019 12:12:11.859 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
27-Mar-2019 12:12:11.859 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Application Command Request (ALIVE:DONE)
27-Mar-2019 12:12:11.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: resetResendCount initComplete=true isDead=false
27-Mar-2019 12:12:11.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
27-Mar-2019 12:12:11.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Incoming command class COMMAND_CLASS_METER, endpoint 1
27-Mar-2019 12:12:11.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: SECURITY NOT required on COMMAND_CLASS_METER
27-Mar-2019 12:12:11.859 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 82: Received COMMAND_CLASS_METER V3 METER_REPORT
27-Mar-2019 12:12:11.860 [DEBUG] [ernal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 82: Meter: Type=Electric(1), Scale=W(2), Value=26.4
27-Mar-2019 12:12:11.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got an event from Z-Wave network: ZWaveMeterValueEvent
27-Mar-2019 12:12:11.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=26.4
27-Mar-2019 12:12:11.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Updating channel state zwave:device:521e1911:node82:meter_watts1 to 26.4 [DecimalType]
27-Mar-2019 12:12:11.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Commands processed 1.
27-Mar-2019 12:12:11.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@28b52f83.
27-Mar-2019 12:12:11.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:11.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:11.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
27-Mar-2019 12:12:11.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
27-Mar-2019 12:12:13.057 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 52 07 60 0D 01 01 25 03 00 E8
27-Mar-2019 12:12:13.058 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 07 60 0D 01 01 25 03 00
27-Mar-2019 12:12:13.058 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 07 60 0D 01 01 25 03 00
27-Mar-2019 12:12:13.058 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
27-Mar-2019 12:12:13.058 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Application Command Request (ALIVE:DONE)
27-Mar-2019 12:12:13.058 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: resetResendCount initComplete=true isDead=false
27-Mar-2019 12:12:13.058 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
27-Mar-2019 12:12:13.058 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 1
27-Mar-2019 12:12:13.058 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
27-Mar-2019 12:12:13.059 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 82: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
27-Mar-2019 12:12:13.059 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 82: Switch Binary report, value = 0
27-Mar-2019 12:12:13.059 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
27-Mar-2019 12:12:13.059 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
27-Mar-2019 12:12:13.059 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Updating channel state zwave:device:521e1911:node82:switch_binary1 to OFF [OnOffType]
27-Mar-2019 12:12:13.059 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Commands processed 1.
27-Mar-2019 12:12:13.059 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6282439b.
27-Mar-2019 12:12:13.059 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:13.059 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:13.060 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
27-Mar-2019 12:12:13.060 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

==> /opt/openhab/userdata/logs/events.log <==
2019-03-27 12:12:13.060 [vent.ItemStateChangedEvent] - Light_MasterBedroom_Ceiling changed from ON to OFF

==> /opt/openhab/userdata/logs/zwave.log <==
27-Mar-2019 12:12:13.858 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 12 00 04 00 52 0C 60 0D 01 01 32 02 21 32 00 00 00 00 F9
27-Mar-2019 12:12:13.858 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 0C 60 0D 01 01 32 02 21 32 00 00 00 00
27-Mar-2019 12:12:13.859 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=82, callback=0, payload=00 52 0C 60 0D 01 01 32 02 21 32 00 00 00 00
27-Mar-2019 12:12:13.859 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
27-Mar-2019 12:12:13.859 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Application Command Request (ALIVE:DONE)
27-Mar-2019 12:12:13.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: resetResendCount initComplete=true isDead=false
27-Mar-2019 12:12:13.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
27-Mar-2019 12:12:13.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: Incoming command class COMMAND_CLASS_METER, endpoint 1
27-Mar-2019 12:12:13.859 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 82: SECURITY NOT required on COMMAND_CLASS_METER
27-Mar-2019 12:12:13.859 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 82: Received COMMAND_CLASS_METER V3 METER_REPORT
27-Mar-2019 12:12:13.859 [DEBUG] [ernal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 82: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
27-Mar-2019 12:12:13.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got an event from Z-Wave network: ZWaveMeterValueEvent
27-Mar-2019 12:12:13.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=0E+1
27-Mar-2019 12:12:13.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 82: Updating channel state zwave:device:521e1911:node82:meter_watts1 to 0 [DecimalType]
27-Mar-2019 12:12:13.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Commands processed 1.
27-Mar-2019 12:12:13.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 82: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@247f1391.
27-Mar-2019 12:12:13.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:13.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:13.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
27-Mar-2019 12:12:13.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
27-Mar-2019 12:12:16.877 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0F 03 25 03 FF 27
27-Mar-2019 12:12:16.878 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 03 25 03 FF
27-Mar-2019 12:12:16.878 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 03 25 03 FF
27-Mar-2019 12:12:16.878 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
27-Mar-2019 12:12:16.878 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Application Command Request (ALIVE:DONE)
27-Mar-2019 12:12:16.878 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: resetResendCount initComplete=true isDead=false
27-Mar-2019 12:12:16.878 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
27-Mar-2019 12:12:16.879 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: SECURITY not supported
27-Mar-2019 12:12:16.879 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 15: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
27-Mar-2019 12:12:16.879 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 15: Switch Binary report, value = 255
27-Mar-2019 12:12:16.879 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 15: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
27-Mar-2019 12:12:16.879 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 15: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=255
27-Mar-2019 12:12:16.879 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Commands processed 1.
27-Mar-2019 12:12:16.879 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3c1416f9.
27-Mar-2019 12:12:16.879 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:16.880 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:16.880 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
27-Mar-2019 12:12:16.880 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

# NOTE: at this point, I would expect to see an entry in events.log saying Light_MasterEnsuite_Ceiling changed from OFF to ON

27-Mar-2019 12:12:22.948 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0F 03 25 03 00 D8
27-Mar-2019 12:12:22.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 03 25 03 00
27-Mar-2019 12:12:22.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 03 25 03 00
27-Mar-2019 12:12:22.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
27-Mar-2019 12:12:22.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Application Command Request (ALIVE:DONE)
27-Mar-2019 12:12:22.949 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: resetResendCount initComplete=true isDead=false
27-Mar-2019 12:12:22.949 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
27-Mar-2019 12:12:22.949 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: SECURITY not supported
27-Mar-2019 12:12:22.949 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 15: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
27-Mar-2019 12:12:22.950 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 15: Switch Binary report, value = 0
27-Mar-2019 12:12:22.950 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 15: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
27-Mar-2019 12:12:22.950 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 15: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
27-Mar-2019 12:12:22.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Commands processed 1.
27-Mar-2019 12:12:22.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3ddcffcf.
27-Mar-2019 12:12:22.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:22.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
27-Mar-2019 12:12:22.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
27-Mar-2019 12:12:22.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

# NOTE: at this point, I would expect to see an entry in events.log saying Light_MasterEnsuite_Ceiling changed from ON to OFF

[sihui]

Check via PaperUI if you have the correct channel linked to your switch itemtype.
If “Switch” and “Switch1” are shown link your item to the opposite one you have right now.

[FloatingBoater (James Derrick)]

Hi,

From recent experience of updating to the 2.4 release, I’d suggest looking at two possibilities:

• Each new release includes a fresh export from Chris’s Z-Wave device database which may have changed the Channels associated with each Thing. For example, I use files to link Channels to Items and the GUI is the best way to spot if the definition of a Channel has changed such as Switch/ Contact, or switch_binary / switch_binary1.
  PaperUI or HABmin both work, although PaperUI give a slightly clearer view in Configuration -> Things -> FGS211 -> Channels.
  How is Light_MasterEnsuite_Ceiling linked to zwave:device:521e1911:node15:switch_binary ? files or GUI? Does the GUI confirm the linkage?

• A change in the Z-Wave binding. Protocol debug is beyond me, but as you’ve collected debug logs already, Chris’s Z-Wave log viewer might help visualise what is going on.

TTFN,

James

[evans_jon (Jon Evans)]

Thanks @sihui and @FloatingBoater.

My Items are defined in text files, Things are defined via the GUI and the channel linking between Things and Items is done in the GUI as well. I can operate all three FGS211 devices via the sitemap and the lights switch off and on instantly, so I think the correct channel is linked. It’s only when operating the switch manually that the Item state doesn’t get updated.

Just going to mention @chris here as well in case he has any insight!

Cheers

Jon

[sihui]

@evans_jon

and the channel linking

We still don’t know which channel you are using.

[evans_jon (Jon Evans)]

@sihui

We still don’t know which channel you are using.

Sorry! Didn’t think it was important if it works OK from openHAB to the device. It’s zwave:device:521e1911:node15:switch_binary1.

Cheers

Jon

[sihui]

@evans_jon

Didn’t think it was important

It isn’t now anymore because you don’t have any endpoint 0 channels available

[sihui]

According to your debug log you don’t get state updates for your FGS211:

I would double check the association group for the controller: for the FGS211 it is group 3, not group 1 like usual.

[evans_jon (Jon Evans)]

It seems correct… I do have what seems to be a general issue where the UI normally looks like it’s unset (it shows “Search”) although in this case it did show as “Controller” when I went to the edit page.

[sihui]

My last idea: set the correct controller group again via HABmin, not PaperUI.

[grelle]

Experiencing exactly this issue, did you get it resolved @evans_jon ?

Might there be a bug to report if not ?

FGS211 with dusk-to-dawn sensor attached

With the possibility that I’m wrong. These devices FGS211 do only have 2 channels. Switch1 and Switch2. At least, there is nothing else to choose from in PaperUI for this “thing”. FGS221 do have 3 channels, Switch, Switch1 and Switch2. But this is FGS211. A 1x3kW relay. And fact is, the state of “Switch 1” get’s updated to “On” when polled after a while when the S1 has been triggered. So. Sort of back to square one, they are not being updated automatically.

[chris (Chris Jackson)]

@grelle

Experiencing exactly this issue

This is really not a helpful description of your problem - please provide more information about your system, logs, problem, etc.

[grelle]

Sorry. Thought it made sense from threadmaker and my link. Here we go.

Hardware:

MacMini model A1347
Aeotech Z-Stick GEN 5 model: ZW090-C (868,42MHz)
Fibaro Relay switch FGS211 v2-1
20+ other z-wave devices including one batterypowered FGMS.
RFXtrx433E - via USB

Software:

Ubuntu 18.04.2 LTS
Openhab2 2.4.0
Z-Wave binding 2.4

One of my FGS211 is wired like this: Analouge (?) dusk-to-dawn sensor wired via an electric relay to S1 on FGS211 Node 24 and a lightbulb connected to output of this node 24.

When dusk sensor triggers the S1 closes on Node 24 and the lightbulb lits. The FGS211 Node 24 is not updating its state to openhab. It only does this:

These are my settings as far as associations matter:

And my mesh lookes like this:

DEBUG log when S1 closes as seen above in z-wave log viewer (either by dusk sensor or manually with physical switch):

2019-09-24 17:14:47.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-24 17:14:47.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2019-09-24 17:14:47.861 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2019-09-24 17:14:47.861 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2019-09-24 17:14:47.862 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2019-09-24 17:14:47.862 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2019-09-24 17:14:47.862 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 3: Switch Binary report, value = 255
2019-09-24 17:14:47.863 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-09-24 17:14:47.863 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_BINARY, value = 255
2019-09-24 17:14:47.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2019-09-24 17:14:47.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5d13aaa6.
2019-09-24 17:14:47.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-24 17:14:47.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-24 17:14:47.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-24 17:14:47.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Steps performed:

• Restart and reboot several times
• Exclusion and inclusion of z-wave devices
• Set and re-set Controller as lifeline in group 3 of the FGS211 associations
• Heal individual nodes
• Heal whole network
• Moved around Controller in house for range issues
• Debug with logs

Lately in my investigation I’ve discovered that all of my 4 or 5 FGS211 behaves the same. Not reporting its status to controller.

It does though update the Items state when performing poll. My item looks like this (where X is my controller ID:

Switch SW_GARAGE_SKYMNING_1 "Switch1 Skymning" <garage_detached> (Switches) { channel="zwave:device:XXXXXXX:node3:switch_binary1" }

[chris (Chris Jackson)]

My strong suggestion is to update to a newer binding. 2.4 is now pretty old, and it doesn’t handle some incorrectly formatted commands that can come from the UI. This can lead to associations getting removed and nodes not reporting state to the controller. If the devices aren’t reporting state, it is almost certainly because the associations are not correctly set.

However I’m also a bit confused about what you are trying to do. It looks from the log image that node 24 is sending an event - I’m not sure how this relates to node 3 that you have then shown further down?

[grelle]

Sorry for that, Node 24 was Node 3 before exclusion/inclusion so the textual log is “older” than my image.

I will go about updating the binding. Thankyou!

[chris (Chris Jackson)]

Ok, understood.

The device is not sending the multi-instance command so the binding isn’t picking up on this. Again, the newer binding may resolve this so let’s see if things improve when you update, and if not we can look at it again then.

You might need to exclude and re-include the device to get it reconfigured completely - otherwise it may not configure for the multi-instance configuration.

[grelle]

Ok, now running:

OpenHAB 2.5.0-SNAPSHOT (#1700)
binding-zwave - 2.5.0.SNAPSHOT

Followed all your steps here ZWave binding updates

Removed all things except controller and then re-added all things from inbox. Found out that these FGS211 behaved like before. Excluded one of them and re-included. Healed it but still reports like noted before without updating state to Openhab.

Have scheduled a network heal for about 45 min from now. Let’s see if that helps, otherwise I think I have followed the steps you wanted me to ?

[evans_jon (Jon Evans)]

Hi @grelle, just to confirm - I never did get this to work with OpenHAB.

[grelle]

Now the network has healed and is all green. Looks like it has the same behaviour though.

Not updating state (this is when physically pressing the switch):

2019-09-26 21:53:53.945 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 19 03 25 03 00 CE 
2019-09-26 21:53:53.946 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 25 03 00 
2019-09-26 21:53:53.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 25 03 00 
2019-09-26 21:53:53.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-26 21:53:53.948 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:DONE)
2019-09-26 21:53:53.948 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: resetResendCount initComplete=true isDead=false
2019-09-26 21:53:53.948 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0
2019-09-26 21:53:53.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported
2019-09-26 21:53:53.949 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2019-09-26 21:53:53.949 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 25: Switch Binary report, value = 0
2019-09-26 21:53:53.950 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-09-26 21:53:53.950 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
2019-09-26 21:53:53.950 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.
2019-09-26 21:53:53.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@219b09fe.
2019-09-26 21:53:53.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-26 21:53:53.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-26 21:53:53.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-26 21:53:53.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

[sihui]

@grelle

Not updating state (this is when physically pressing the switch)

@grelle

Ok, will attach a classic switch to try.

Is this now a classic switch or still your dusk/dawn sensor?