[Solved] Weird behaviour with Fibaro 212 dimmers; erratic or no updates

Setup, Configuration and Use Installation
1

  • Platform information:

    • Hardware: x86
    • OS: official docker image (49309c386441)
    • Java Runtime Environment: included in docker image
    • openHAB version: 2.4

  • Issue of the topic: please be detailed explaining your issue
    My dimmers are behaving erratically since my upgrade to 2.4. Of course I’ve seen the mention that you should re-add zwave devices when upgrading; which I did. Even excluding and re-including.
    I have 4 problematic dimmers, “Fibaro Dimmer 2”. Each show one or more problems of the following:

    • State changes invoked by physical switches not reflected in UI
    • Power sensor not updated
    • Power sensor consistently shows Power usage of the previous state. So from a freshly started Openhab, and the dimmer being off, turning ON, and the OFF, the power usage would be 200W (which is correct for the ON state). Turning ON again, would change the power usage to 0W, or some small value, as if the power usage was in the middle of transitioning to the ON status’ corresponding power level.

However, on Zwave level all things seem to be in order, as correct power usage and dimmer level updates actually come by, but it seems like they’re ignored? Here is a log snippet turning ON then OFF. The command used is "$ tail -f /opt/openhab/userdata/logs/openhab.log |grep -v “NODE 19” |grep -i “value =”
" Node 19 is really chatty so that’s why it’s excluded explicitly in the command

2019-01-27 14:37:43.257 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 11: Switch Multi Level report, value = 99
2019-01-27 14:37:43.258 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 99
2019-01-27 14:37:43.788 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Sensor Value = 33.7
2019-01-27 14:37:43.788 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 33.7
2019-01-27 14:37:43.838 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 11: Switch Multi Level report, value = 99
2019-01-27 14:37:43.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 99
2019-01-27 14:37:45.424 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Sensor Value = 199.7
2019-01-27 14:37:45.424 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 199.7
2019-01-27 14:37:48.428 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Sensor Value = 199.5
2019-01-27 14:37:48.429 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 199.5
2019-01-27 14:37:55.379 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 11: Switch Multi Level report, value = 0
2019-01-27 14:37:55.382 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 0
2019-01-27 14:37:55.906 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Sensor Value = 199.5
2019-01-27 14:37:55.907 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 199.5
2019-01-27 14:37:55.972 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 11: Switch Multi Level report, value = 0
2019-01-27 14:37:55.975 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 0
2019-01-27 14:37:58.449 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Sensor Value = 0E+1
2019-01-27 14:37:58.450 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 0E+1

But what was actually seen in the UI is:
After turning ON: Power usage is 33.7. (even after multiple seconds). Then when I turn the dimmer off, the power usage is 199.5, whereas the log definitely shows that it should converge to 0E+1

I’ve already cleared userdata/cache and userdata/tmp. I’m really at my wit’s end with this one.

  • Please post configurations (if applicable):
    • Items configuration related to the issue
      All done through UI
2

Try setting the Command Poll Period a little higher:

grafik

And of course make sure you have the association group set to your controller.

3

That would indicate that the problem is on zwave level, however I can see the status updates coming in fine in the openhab.log. Might I add that till 2.3 everything was rock solid.
Nonetheless, I tried the command poll thing, again, bc I already tried that previously, still the same issues.

I even get updates with the correct vales like:

2019-01-27 20:18:49.708 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Updating channel state zwave:device:87ad7b53:node11:sensor_power1 to 61.9 [DecimalType]

But those are not actually used to set the corresponding item’s state

4

Did you try the sensor_power channel instead of sensor_power1?

5

tried them both, same behaviour.

6

But isn’t it weird that I get updates like

2019-01-27 20:18:49.708 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Updating channel state zwave:device:87ad7b53:node11:sensor_power1 to 61.9 [DecimalType]

But the item’s state does not get updated? I checked if it was actually updated by querying its state through the karaf console, so it’s not a UI thing, and also not a Zwave thing – imo

7

Errors in openhab.log?
I don’t use the pwr channels, if I find the time tomorrow I will test with my FGD212.

8

Openhab.log is error free :\

9

Seems I stand corrected, beginning with a minimal configuration, but leaving zwave intact wrt added devices on zwave-level showed that it should just work with sensor_power1.
Please do not invest your time in this just yet.I’ll update here when I’ve zoomed in to the actual cause.

10

I did :grinning:, here are my findings. I did only take a quick look, dos not look too bad, please feel free to take a deeper look:

switch_dimmer1 to ON via GUI:
2019-01-29 07:41:12.458 [ome.event.ItemCommandEvent] - Item 'FibFGD212_1_Sw' received command ON
2019-01-29 07:41:12.480 [nt.ItemStatePredictedEvent] - FibFGD212_1_Sw predicted to become ON
2019-01-29 07:41:12.509 [vent.ItemStateChangedEvent] - FibFGD212_1_Sw changed from OFF to ON
2019-01-29 07:41:13.514 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 0 to 100
2019-01-29 07:41:15.950 [vent.ItemStateChangedEvent] - FibFGD212_1_Watts1 changed from 0 to 0.1
2019-01-29 07:41:18.707 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 0.1 to 13.7

switch_dimmer1 to OFF via GUI:
2019-01-29 07:47:15.514 [ome.event.ItemCommandEvent] - Item 'FibFGD212_1_Sw' received command OFF
2019-01-29 07:47:15.536 [nt.ItemStatePredictedEvent] - FibFGD212_1_Sw predicted to become OFF
2019-01-29 07:47:15.564 [vent.ItemStateChangedEvent] - FibFGD212_1_Sw changed from ON to OFF
2019-01-29 07:47:16.575 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 100 to 0
2019-01-29 07:47:17.184 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 13.7 to 7
2019-01-29 07:47:18.792 [vent.ItemStateChangedEvent] - FibFGD212_1_Kwh1 changed from 1.78 to 1.79
2019-01-29 07:47:18.836 [vent.ItemStateChangedEvent] - FibFGD212_1_Watts1 changed from 0.1 to 7
2019-01-29 07:47:26.839 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 7 to 0

switch_dimmer1 via GUI slider from 0 to 53%:
2019-01-29 07:52:47.528 [ome.event.ItemCommandEvent] - Item 'FibFGD212_1_Dim' received command 53
2019-01-29 07:52:47.550 [nt.ItemStatePredictedEvent] - FibFGD212_1_Dim predicted to become 53
2019-01-29 07:52:47.579 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 0 to 53
2019-01-29 07:52:47.960 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 0 to 0.4
2019-01-29 07:52:48.282 [vent.ItemStateChangedEvent] - FibFGD212_1_Sw changed from OFF to ON
2019-01-29 07:52:50.842 [vent.ItemStateChangedEvent] - FibFGD212_1_Watts1 changed from 7 to 0.4
2019-01-29 07:52:53.956 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 0.4 to 7

switch_dimmer1 via GUI slider from 53% to 80%:
2019-01-29 07:55:35.684 [ome.event.ItemCommandEvent] - Item 'FibFGD212_1_Dim' received command 80
2019-01-29 07:55:35.712 [nt.ItemStatePredictedEvent] - FibFGD212_1_Dim predicted to become 80
2019-01-29 07:55:35.742 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 53 to 80
2019-01-29 07:55:37.020 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 7 to 10.9
2019-01-29 07:55:38.999 [vent.ItemStateChangedEvent] - FibFGD212_1_Watts1 changed from 0.4 to 10.9
2019-01-29 07:55:42.012 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 10.9 to 11.9

switch_dimmer1 via GUI slider from 80% to 24%:
2019-01-29 07:56:54.328 [ome.event.ItemCommandEvent] - Item 'FibFGD212_1_Dim' received command 24
2019-01-29 07:56:54.350 [nt.ItemStatePredictedEvent] - FibFGD212_1_Dim predicted to become 24
2019-01-29 07:56:54.378 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 80 to 24
2019-01-29 07:56:55.042 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 11.9 to 10.3
2019-01-29 07:56:57.687 [vent.ItemStateChangedEvent] - FibFGD212_1_Watts1 changed from 10.9 to 10.3
2019-01-29 07:57:00.042 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 10.3 to 3

switch_dimmer1 to OFF via physical switch:
2019-01-29 07:58:52.562 [vent.ItemStateChangedEvent] - FibFGD212_1_Sw changed from ON to OFF
2019-01-29 07:58:52.585 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 24 to 0
2019-01-29 07:58:53.080 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 3 to 1.7
2019-01-29 07:59:03.092 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 1.7 to 0

switch_dimmer1 to 15% via physical switch:
2019-01-29 08:05:14.084 [vent.ItemStateChangedEvent] - FibFGD212_1_Sw changed from OFF to ON
2019-01-29 08:05:14.324 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 0 to 15
2019-01-29 08:05:14.353 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 0 to 1.4
2019-01-29 08:05:19.265 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 1.4 to 2.3

switch_dimmer1 to OFF via physical switch:
2019-01-29 08:05:57.168 [vent.ItemStateChangedEvent] - FibFGD212_1_Sw changed from ON to OFF
2019-01-29 08:05:57.198 [vent.ItemStateChangedEvent] - FibFGD212_1_Dim changed from 15 to 0
2019-01-29 08:05:58.316 [vent.ItemStateChangedEvent] - FibFGD212_1_Pwr1 changed from 2.3 to 0
11

Yeah I can’t reproduce this anymore… quite the voodoo, something must’ve been in a weird state. I manually combed through the json databases and removed all channel-item entries which had to do with zwave Things; but I’m not sure if that was the thing that actually solved everything.
Just glad all is working robustly again. @sihui thanks for the power_sensor1 tip and the rest of the help.

1 Like