[SOLVED] SCENE_ACTIVATION not working in new FGD-212

mstormi · June 24, 2018, 4:32pm

Hi

I’ve got a (fairly new) Fibaro FGD-212 to send SCENE_ACTIVATION, but OH does not translate those messages into an event.
It’s sending SCENE_ACTIVATION V0 with a time=0 parameter.
For comparison, an older FGD-211 to work for scenes sends SCENE_ACTIVATION V1 with time=255, see log at the end.
Using latest dev version of the zwave binding already.

Any idea (short of restarting OH which I’ve not done yet) ?

Here’s the bad one’s log:

2018-06-24 17:52:50.206 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 10 08 56 01 2B 01 18 00 F2 A1 DB
2018-06-24 17:52:50.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 08 56 01 2B 01 18 00 F2 A1
2018-06-24 17:52:50.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 08 56 01 2B 01 18 00 F2 A1
2018-06-24 17:52:50.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 08 56 01 2B 01 18 00 F2 A1
2018-06-24 17:52:50.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-06-24 17:52:50.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Application Command Request (ALIVE:DONE)
            2018-06-24 17:52:50.238 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: resetResendCount initComplete=true isDead=false
            2018-06-24 17:52:50.239 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
            2018-06-24 17:52:50.240 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
            2018-06-24 17:52:50.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY NOT required on COMMAND_CLASS_SCENE_ACTIVATION
            2018-06-24 17:52:50.242 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Received COMMAND_CLASS_SCENE_ACTIVATION V0 SCENEACTIVATION_SET
            2018-06-24 17:52:50.243 [DEBUG] [ass.ZWaveSceneActivationCommandClass] - NODE 16: Scene activation: Scene 24, Time 0
            2018-06-24 17:52:50.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
            2018-06-24 17:52:50.246 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SCENE_ACTIVATION, value = 24
            2018-06-24 17:52:50.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Commands processed 1.
            2018-06-24 17:52:50.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@15c1629.

Here’s the version section from the node’s .xml:

    <commandClass>COMMAND_CLASS_VERSION</commandClass>
    <COMMAND__CLASS__VERSION>
      <version>2</version>
      <instances>1</instances>
      <versionSupported>2</versionSupported>
      <libraryType>LIB_SLAVE_ENHANCED</libraryType>
      <protocolVersion>4.5</protocolVersion>
      <applicationVersion>3.5</applicationVersion>
      <hardwareVersion>2</hardwareVersion>
    </COMMAND__CLASS__VERSION>

log of working FGD-211:

2018-06-24 17:53:19.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Application Command Request (ALIVE:DONE)
2018-06-24 17:53:19.652 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: resetResendCount initComplete=true isDead=false
2018-06-24 17:53:19.652 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-06-24 17:53:19.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: SECURITY not supported
2018-06-24 17:53:19.654 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 32: Received COMMAND_CLASS_SCENE_ACTIVATION V1 SCENEACTIVATION_SET
2018-06-24 17:53:19.655 [DEBUG] [ass.ZWaveSceneActivationCommandClass] - NODE 32: Scene activation: Scene 24, Time 255
2018-06-24 17:53:19.656 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-06-24 17:53:19.657 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SCENE_ACTIVATION, value = 24
2018-06-24 17:53:19.658 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Updating channel state zwave:device:ddd23e6c:node32:scene_number to 24 [DecimalType]
2018-06-24 17:53:19.661 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Commands processed 1.
2018-06-24 17:53:19.662 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@127800.
2018-06-24 17:53:19.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking transaction 138292  ApplicationCommandHandler.
2018-06-24 17:53:19.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking transaction : state >> WAIT_RESPONSE
2018-06-24 17:53:19.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking transaction : node  >> 103
2018-06-24 17:53:19.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking transaction : class >> 43 == 38.
2018-06-24 17:53:19.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking transaction : commd >> 1 == 3.
2018-06-24 17:53:19.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Ignoring transaction since not waiting for data.

chris · June 24, 2018, 5:07pm

There’s nothing obviously wrong from this log. Maybe the channel isn’t linked or something like that? There’s absolutely no logic in the converter, so assuming the channel is linked it should work.

I’d suggest to check the initialisation logs to see what is going on there.

mstormi · June 24, 2018, 5:58pm

Suspected that, too, but I already deleted + readded the item, resulting in
2018-06-24 18:12:35.463 [.ItemChannelLinkAddedEvent] - Link 'Szenenschalter_Bad_Tuer-zwave:device:ddd23e6c:node16:scene_number' has been added.
so I believe the link is there.
Restarted OH now, channel linking shows up properly, but still no luck.

Is that V0,time=0 vs. V1,time=255 (from the working device) of significance ?

chris · June 24, 2018, 6:07pm

No - the data is still being decoded and sent as an event -:

2018-06-24 17:52:50.243 [DEBUG] [ass.ZWaveSceneActivationCommandClass] - NODE 16: Scene activation: Scene 24, Time 0
2018-06-24 17:52:50.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-06-24 17:52:50.246 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SCENE_ACTIVATION, value = 24

So the thing handler is receiving the message ok but not passing it to the processor.

As suggested, please check the log during initialisation to see what is happening during the channel initialisation. If you’re not sure what to look for, then please provide it for me to take a look at.

mstormi · June 24, 2018, 7:16pm

Hopefully this is what you mean (I filtered the full log for lines to contain NODE 16 (zwave debug) or node16 (part of the channel name).
This was a full OH restart. If that log excerpt doesn’t show what you’re looking for let me know where to upload the full log, please.
Yes you’re right there is no initialization of a scene_number channel for node 16, I double-checked the whole log, too.

2018-06-24 20:32:25.857 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery resolved to thingType zwave:fibaro_fgd212_03_005
2018-06-24 20:32:25.861 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Starting initialisation from EMPTYNODE
2018-06-24 20:32:25.934 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to IDENTIFY_NODE
2018-06-24 20:32:26.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: Initialisation starting
2018-06-24 20:32:25.934 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 16: Init node thread finished
2018-06-24 20:32:48.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller status changed to ONLINE.
2018-06-24 20:32:48.430 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller is ONLINE. Starting device initialisation.
2018-06-24 20:32:48.478 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties.
2018-06-24 20:32:48.492 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties. MAN=271
2018-06-24 20:32:48.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties. MAN=271. SET. Was 271
2018-06-24 20:32:48.520 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Properties synchronised
2018-06-24 20:32:48.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1_1]]: Adding node_1_1
2018-06-24 20:32:48.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising Thing Node...
2018-06-24 20:32:48.625 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer for OnOffType
2018-06-24 20:32:48.627 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer for PercentType
2018-06-24 20:32:48.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:switch_dimmer for PercentType
2018-06-24 20:32:48.630 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:sensor_power for DecimalType
2018-06-24 20:32:48.632 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:sensor_power for DecimalType
2018-06-24 20:32:48.634 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_kwh for DecimalType
2018-06-24 20:32:48.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_kwh for DecimalType
2018-06-24 20:32:48.638 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_watts for DecimalType
2018-06-24 20:32:48.674 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_watts for DecimalType
2018-06-24 20:32:48.681 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_heat for OnOffType
2018-06-24 20:32:48.682 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_heat for OnOffType
2018-06-24 20:32:48.690 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_power for OnOffType
2018-06-24 20:32:48.816 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_power for OnOffType
2018-06-24 20:32:48.820 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_system for OnOffType
2018-06-24 20:32:48.822 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_system for OnOffType
2018-06-24 20:32:48.833 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer1 for OnOffType
2018-06-24 20:32:48.835 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer1 for PercentType
2018-06-24 20:32:48.841 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:switch_dimmer1 for PercentType
2018-06-24 20:32:48.850 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:sensor_power1 for DecimalType
2018-06-24 20:32:48.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:sensor_power1 for DecimalType
2018-06-24 20:32:48.854 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_kwh1 for DecimalType
2018-06-24 20:32:48.866 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_kwh1 for DecimalType
2018-06-24 20:32:48.868 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_watts1 for DecimalType
2018-06-24 20:32:48.870 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_watts1 for DecimalType
2018-06-24 20:32:48.875 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_heat1 for OnOffType
2018-06-24 20:32:48.876 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_heat1 for OnOffType
2018-06-24 20:32:48.891 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_power1 for OnOffType
2018-06-24 20:32:48.893 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_power1 for OnOffType
2018-06-24 20:32:48.895 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_system1 for OnOffType
2018-06-24 20:32:48.898 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_system1 for OnOffType
2018-06-24 20:32:48.900 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer2 for OnOffType
2018-06-24 20:32:48.905 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer2 for PercentType
2018-06-24 20:32:48.908 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:switch_dimmer2 for PercentType
2018-06-24 20:32:48.924 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling intialised at 1800 seconds - start in 529200 milliseconds.
2018-06-24 20:32:48.933 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Device initialisation complete.
2018-06-24 20:32:51.464 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: ProtocolInfo
2018-06-24 20:32:51.485 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Listening = true
2018-06-24 20:32:51.495 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Routing   = true
2018-06-24 20:32:51.507 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Beaming   = true
2018-06-24 20:32:51.539 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Version   = 4
2018-06-24 20:32:51.540 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: FLIRS     = false
2018-06-24 20:32:51.541 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Security  = false
2018-06-24 20:32:51.545 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Max Baud  = 40000
2018-06-24 20:32:51.548 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Basic    = BASIC_TYPE_ROUTING_SLAVE
2018-06-24 20:32:51.551 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Generic  = GENERIC_TYPE_SWITCH_MULTILEVEL
2018-06-24 20:32:51.561 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 16: Specific = SPECIFIC_TYPE_POWER_SWITCH_MULTILEVEL
2018-06-24 20:32:51.564 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2018-06-24 20:32:51.567 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2018-06-24 20:32:51.583 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 16: Version = 1, version set. Enabling extra functionality.

Triple-pressed the button to re-include the device. Again no scene channel:

2018-06-24 21:17:00.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to STATIC_END
2018-06-24 21:17:00.201 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-06-24 21:17:00.202 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties.
2018-06-24 21:17:00.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties. MAN=271
2018-06-24 21:17:00.205 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Updating node properties. MAN=271. SET. Was 271
2018-06-24 21:17:00.207 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Properties synchronised
2018-06-24 21:17:00.236 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=Lifeline, profile1=0, profile2=1, associations=[node_1_1]]: Adding node_1_1
2018-06-24 21:17:00.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration synchronised
2018-06-24 21:17:00.283 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Setting ONLINE
2018-06-24 21:17:00.286 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising Thing Node...
2018-06-24 21:17:00.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer for OnOffType
2018-06-24 21:17:00.290 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer for PercentType
2018-06-24 21:17:00.291 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:switch_dimmer for PercentType
2018-06-24 21:17:00.293 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:sensor_power for DecimalType
2018-06-24 21:17:00.295 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:sensor_power for DecimalType
2018-06-24 21:17:00.296 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_kwh for DecimalType
2018-06-24 21:17:00.298 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_kwh for DecimalType
2018-06-24 21:17:00.299 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_watts for DecimalType
2018-06-24 21:17:00.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_watts for DecimalType
2018-06-24 21:17:00.302 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_heat for OnOffType
2018-06-24 21:17:00.304 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_heat for OnOffType
2018-06-24 21:17:00.305 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_power for OnOffType
2018-06-24 21:17:00.306 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_power for OnOffType
2018-06-24 21:17:00.308 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_system for OnOffType
2018-06-24 21:17:00.309 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_system for OnOffType
2018-06-24 21:17:00.311 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer1 for OnOffType
2018-06-24 21:17:00.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer1 for PercentType
2018-06-24 21:17:00.314 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:switch_dimmer1 for PercentType
2018-06-24 21:17:00.316 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:sensor_power1 for DecimalType
2018-06-24 21:17:00.318 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:sensor_power1 for DecimalType
2018-06-24 21:17:00.319 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_kwh1 for DecimalType
2018-06-24 21:17:00.320 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_kwh1 for DecimalType
2018-06-24 21:17:00.322 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:meter_watts1 for DecimalType
2018-06-24 21:17:00.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:meter_watts1 for DecimalType
2018-06-24 21:17:00.324 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_heat1 for OnOffType
2018-06-24 21:17:00.325 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_heat1 for OnOffType
2018-06-24 21:17:00.327 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_power1 for OnOffType
2018-06-24 21:17:00.329 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_power1 for OnOffType
2018-06-24 21:17:00.330 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:alarm_system1 for OnOffType
2018-06-24 21:17:00.331 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:alarm_system1 for OnOffType
2018-06-24 21:17:00.332 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer2 for OnOffType
2018-06-24 21:17:00.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising cmd channel zwave:device:ddd23e6c:node16:switch_dimmer2 for PercentType
2018-06-24 21:17:00.335 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising state channel zwave:device:ddd23e6c:node16:switch_dimmer2 for PercentType
2018-06-24 21:17:00.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling intialised at 1800 seconds - start in 732600 milliseconds.
2018-06-24 21:17:00.338 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 16: Serialise aborted as static stages not complete
2018-06-24 21:17:00.339 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer - advancing to DYNAMIC_VALUES
2018-06-24 21:17:00.340 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-06-24 21:17:00.341 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_METER
2018-06-24 21:17:00.342 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Found 1 instances of COMMAND_CLASS_METER for endpoint 0

mstormi · June 24, 2018, 7:53pm

Update: excluded, reincluded device. Now I see a scene_number channel linked, and while I get a SCENE_ACTIVATION message in, the binding now claims it does not know about the command class for that device. Right, it’s missing in the .XML. Tried reinitializing twice already, makes no difference. Puzzled …

2018-06-24 21:50:48.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:DONE)
2018-06-24 21:50:48.767 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false
2018-06-24 21:50:48.768 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2018-06-24 21:50:48.768 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-06-24 21:50:48.769 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command class COMMAND_CLASS_SCENE_ACTIVATION not found.
2018-06-24 21:50:48.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.

I saw this ‘unsupported 43 command’ during initialization after inclusion:

2018-06-24 21:43:03.338 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: SendData Request. CallBack ID = 52, Status = Transmission complete and ACK received(0)
2018-06-24 21:43:03.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 2217: Transaction not completed
2018-06-24 21:43:03.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:STATIC_VALUES)
2018-06-24 21:43:03.377 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0
2018-06-24 21:43:03.378 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY NOT required on COMMAND_CLASS_ASSOCIATION_GRP_INFO
2018-06-24 21:43:03.390 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_ASSOCIATION_GRP_INFO V1 ASSOCIATION_GROUP_INFO_LIST_REPORT
2018-06-24 21:43:03.392 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26: Supported Command classes and commands for group:1 ->
2018-06-24 21:43:03.394 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26:   COMMAND_CLASS_SWITCH_MULTILEVEL command:3
2018-06-24 21:43:03.396 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26:   COMMAND_CLASS_DEVICE_RESET_LOCALLY command:1
2018-06-24 21:43:03.397 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26:   unsupported 43 command:1
2018-06-24 21:43:03.399 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26:   COMMAND_CLASS_SENSOR_MULTILEVEL command:5
2018-06-24 21:43:03.400 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26:   COMMAND_CLASS_METER command:2
2018-06-24 21:43:03.404 [DEBUG] [WaveAssociationGroupInfoCommandClass] - NODE 26:   COMMAND_CLASS_ALARM command:5
2018-06-24 21:43:03.414 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.

chris · June 25, 2018, 7:11am

Yep - thanks, that’s what I was after.

So, this log doesn’t show any scene channels being initialised (unless I missed it in the long list ). Possibly it wasn’t in the database previously and now that you’ve excluded/reincluded it’s sorted itself out (you didn’t need to do this by the way - just deleting the thing, and adding it back is all that’s needed to pick up the latest database definition).

Is the command class advertised in the NIF? Can you see this in the XML? A device is required to advertise all command classes in the NIF, and if it doesn’t do this, then we need to update the database to force this manually.

In the past, we used to add unknown command classes if they were heard like this, but if there were corrupted frames, that caused other problems.

I’ll have a look at this, but I don’t think it’s related.

mstormi · June 25, 2018, 7:58am

[09:51:20] openhabian@openhabianpi:/var/lib/openhab2/zwave$ ls *_26*
network_c602b032__node_26.xml
[09:51:23] openhabian@openhabianpi:/var/lib/openhab2/zwave$ grep -i scene *_26*

As written, no. Even forcefully deleted XML so it’s recreated for sure from device-advertised data (26 is the new node ID after re-inclusion).

Given it’s a command class that existed in predecessor versions of the product (and the device even trying to make use of it), it should be made available like that I think.

You’re right that still would just be a workaround, so let me know what I can do to find out why the device does not advertise the command class. That re-inclusion I made was a first attempt to find out.
Maybe reset the whole actuator to factory defaults ?

chris · June 25, 2018, 11:07am

Sorry if I missed this - I don’t see that anywhere? If it’s not in the NIF then we need to force this command class in the database (using the ADD option if I remember correctly).

Sorry - what do you mean by “made available like that”? Do you mean the binding should add the support for adding classes that are not reported in the NIF in the same way as before? If so, I don’t really agree - it was removed to avoid errors and there are other means to add this command class which can be used for non-compliant devices like this?

Sorry if I misunderstand so feel free to correct me.

mstormi · June 25, 2018, 1:37pm

So that command class is not in the NIF (seems my “as written” statement caused you some confusion - I did’t show any NIFs in my earlier posts, just made the statement that the scene class isn’t in there).
I don’t know how to best get OH/the binding to accept it - I thought the only way is to statically add it to the database, but if you say there’s better means then please choose whatever you feel is most appropriate.
To decide how to do that best is what I meant to ask you for.

Then again, I feel something’s still wrong here. A device to know the class (remember it was included in messages) but to not announce it ? Can’t believe that’s how Fibaro intended to build it. Maybe I’m missing something substantial.
I’m gonna reset that device first to see if that makes a difference.

chris · June 25, 2018, 1:48pm

Correct - this is the only option.

There are many examples of non-compliant devices. Manufacturers presumably don’t go out with the intention of being non-compliant - they just miss something and it ends up non-compliant.

mstormi · June 25, 2018, 4:45pm

Just resetted the dimmer, included it, but no luck i.e. no change in behavior.
Still no scene class(es) in XML or NIF, but SCENE_ACTIVATION is sent on S2 button presses.
So it seems Fibaro screwed it up this time, right?
Could you please let me know how to proceed to get the class added to the database ? Firmware version see .XML in my first post.

chris · June 25, 2018, 5:00pm

I’ve updated the database. After the next update in a few days you will need to delete the thing and add it back so that your system picks up the latest definition.

mstormi · June 25, 2018, 5:02pm

Great, thanks. Mind I’m running the dev version of the binding.

chris · June 26, 2018, 10:24pm

I’ve just updated the binding. Let me know if it helps (note that you must delete the thing and add it again so that it picks up the new definition).

mstormi · June 28, 2018, 6:38am

Thanks. Running it. But something’s strange, the whole thing does not work the way I expect it to.
At first, on receiving SCENE_ACTIVATION, binding did still tell me it doesn’t know that class for that device.
Faked its XML (copied another FGD-212’s and changed node ID) to get it to work, played with the parameters and associations and right now, the device is actually sending SWITCH_MULTILEVEL on EP2 (switch_dimmer2) instead of CENTRAL_SCENE or SCENE_ACTIVATION although scene functionality is enabled on S2. Strange, it’s exactly what that guy in that other thread wanted and I told him NOT to set it up like that but to use scenes, now I do myself and don’t know why.
(btw, at least it’s working with the dev binding, including to decode the endpoint, and this is generating an OH event, and I even make use of that for now as long as I don’t get to see scene events).

Second, according to the XML of some other FGD-212 device of different firmware, it cannot do SCENE_ACTIVATION anymore as FGD-211s did but now it knows about CENTRAL_SCENE only. Then again SCENE_ACTIVATION is what I saw being sent. I vaguely believe to recall you once mentioned both of them are mapped to the same, but I don’t know if the current dev binding does, so when I see SCENE_ACTIVATION in binding debug I’m not sure if it really received that or got CENTRAL_SCENE and it was mapped.
Did you statically add SCENE_ACTIVATION or CENTRAL_SCENE classes to the device or both ? If the former, I guess that at least would explain my first observation.

chris · June 28, 2018, 8:37am

Just to confirm - you deleted the thing, and the original XML, and then added it back again? If so, can you provide the debug log of the initialisation and I’ll see if I can see why it wasn’t added.

Can you provide the XML please. I don’t think I’ve seen the XML and I’d like to confirm what classes are in the NIF. I do however agree that it’s strange if the device is really sending SCENE_ACTIVATION if it’s not supported… I know a lot of devices move to CENTRAL_SCENE which is better designed for use with controllers.

No - they are different command classes and not linked.

Only scene_activation since that’s what you asked for.

I don’t understand this - if we added the SCENE_ACTIVATION command class, then you should not have had the issue that the class was not known right?

mstormi · June 28, 2018, 12:21pm

Deleted thing but not the XML before resetting/including (then again it was a new nodeID so there was not any XML for that node).
Had some severe problems at that stage after I replaced the binding file, though, to require several OH restarts, now it’s too difficult to find that again.
Now given I need to reset my device once more anyway (no idea else how to make it send scenes again),
will do and send you the output.

Here you are. Unlike I thought it’s the same firmware level as my ‘bad’ one.
network_c602b032__node_104.xml (49.0 KB)
Here’s also the current XML of the bad device, last updated during tonight’s network heal, i.e. after I faked XML + included it yesterday: network_c602b032__node_27.xml (48.9 KB)

If the device had been sending CENTRAL_SCENE (the other device to only have that class being a hint) and both classes had been linked to be processed just as SCENE_ACTIVATION was by some common code as I thought I remembered, it could have been just a bad debug output on that part. But since you said they aren’t linked, never mind (I’m still sure we at least discussed that at some point in time, but yes that was well ages ago).

mstormi · June 28, 2018, 3:03pm

Update:
It now works as expected.
Most recent XML created on re-inclusion contains SCENE_ACTIVATION class but no CENTRAL_SCENE now. Device is sending SCENE_ACTIVATION (plus another SWITCH_MULTILEVEL) while before it was only sending the latter. Had to configure scene activation parameter forth and back once or twice to make that work.
First try was to delete XML and re-include, second to ex- and include, and that one was finally successful although I and needed to restart the binding to make it work.
network_c602b032__node_27.xml (46.4 KB)
exinclude.xml (391.3 KB) (sorry for faking file type to get it uploaded)

Thanks for your help in adding the class.

PS: no idea where that CENTRAL_SCENE came from in that other device #104… maybe depends on whether there’s a switch attached to S2 at inclusion time (there isn’t any switch attached to #104). Saw that with Qubino actuators earlier but first time with Fibaros.

chris · June 28, 2018, 3:22pm

Thanks. I guess the problem was simply not removing the XML. This would have meant that the binding used the XML data and didn’t try to discover the services again.