Random Events Triggering After Panel Button Clicked


(Greg Jessup) #1

I have tested this with both HabPanel and Classic UI.

I have an on/off button for a Z-Wave Dimmer switch Called “KitchenMain”

When I click this button. The following events are processed.

2019-03-05 11:39:26.033 [ome.event.ItemCommandEvent] - Item ‘KitchenMain’ received command OFF
2019-03-05 11:39:26.072 [nt.ItemStatePredictedEvent] - KitchenMain predicted to become OFF
2019-03-05 11:39:26.094 [vent.ItemStateChangedEvent] - KitchenMain changed from 100 to 0
2019-03-05 11:39:27.743 [vent.ItemStateChangedEvent] - KitchenMain changed from 0 to 49

Notice that a random event occurs changing the dimmer from 0-49. The light remains off despite seeing this in the log. However my dimmer button changes to 49.

A Similar issue occurs when turned back on.

2019-03-05 11:46:47.190 [ome.event.ItemCommandEvent] - Item ‘KitchenMain’ received command ON
2019-03-05 11:46:47.209 [nt.ItemStatePredictedEvent] - KitchenMain predicted to become ON
2019-03-05 11:46:47.218 [vent.ItemStateChangedEvent] - KitchenMain changed from 0 to 100
2019-03-05 11:46:48.847 [vent.ItemStateChangedEvent] - KitchenMain changed from 100 to 51

The light stays on, looks like it’s 100% but the dimmer switch on the UI Panel goes to 51.

Any idea where these may be coming from?


(Rich Koshak) #2

Do you have any Rules that update this Item for any reason?

What is the make and model of the dimmer?


(Greg Jessup) #3

No Rules.

GE Smart Dimmer 14294.

Is there any debug level that could be increased to try to see where the event is coming from?


(Rich Koshak) #4

You can put the zwave binding into debug or trace mode and watch the binding logs. If the event is coming from the device you should see message traffic coming from there.


(Greg Jessup) #5

Ok After the device was turned. There is a command coming from ZWaveCommandClass that is setting the dimmer value. Any idea what that is?

2019-03-05 16:30:04.888 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 4: Received COMMAND_CLASS_SWITCH_MULTILEVEL V2 SWITCH_MULTILEVEL_REPORT
2019-03-05 16:30:04.889 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Switch Multi Level report, value = 46
2019-03-05 16:30:04.891 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2019-03-05 16:30:04.893 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-03-05 16:30:04.894 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=46
2019-03-05 16:30:04.896 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Checking channel=zwave:device:61de6363:node4:switch_dimmer, cmdClass=COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint=0
2019-03-05 16:30:04.898 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:61de6363:node4:switch_dimmer to 46 [PercentType]
2019-03-05 16:30:04.900 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Checking channel=zwave:device:61de6363:node4:switch_dimmer, cmdClass=COMMAND_CLASS_BASIC, endpoint=0
2019-03-05 16:30:04.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Commands processed 1.
2019-03-05 16:30:04.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5ea60d.

==> /var/log/openhab2/events.log <==
2019-03-05 16:30:04.907 [vent.ItemStateChangedEvent] - KitchenMain changed from 0 to 46


(Rich Koshak) #6

That’s really weird behavior but I think this pretty definitively identifies the culprit. For some reason, the device itself is reporting this new value.

I’ve no further advice from here except to check your other devices to make sure your association groups are not somehow interacting with this device.

Whatever is happening, it’s happening outside of OH though. The binding is doing it’s job and updating the Item based on what the device is telling it.

Unless I’m completely reading these logs wrong.


(Rossko57) #7

Seems relevant


(Greg Jessup) #8

Thanks @rlkoshak and @rossko57 (for the link)
While I’d love to understand what is actually happening and the potential issues I may see with this the following steps fixed the behavior.

With the GE switches and using HabMin.

I went to Things and chose the switch. Then set “Command Poll Period” under “Device Configuration” to 3000 (formerly 1500) and it fixed the behavior.


(Rossko57) #9

Let’s work through.

11:46:47.190 ... Item ‘KitchenMain’ received command ON
11:46:47.209 ... KitchenMain predicted to become ON
11:46:47.218 ... KitchenMain changed from 0 to 100
11:46:48.847 ... KitchenMain changed from 100 to 51

First the command comes from your rule or UI. We know your binding is going to pass that along to your device.

Second, there’s a prediction. Your Item has autoupdate enabled, and this is what autoupdate does. Guesses what the outcome of a command will be.

Third, the Item is updated according to autoupdate’s prediction.
It’s a dimmer, so autoupdate has guessed ON means 100%. Maybe it’s the kind of dimmer that actually turns on at a remembered value from last use - but autoupdate doesn’t know, cannot guess. This is the best guess it has.

That’s all over in a few milliseconds, because its all happening internal to openHAB.

A second later, we get another update. That’s come from the device, via the binding. I don’t know but can guess that is actually a response from the device to being sent the ON command, seems a reasonable thing to do.
But … what “should” be the value of that response? It might be “this is what I got right now”. Does that mean before, after, or during the turning-up/on process? Does it mean “this is what I will get afterwards”?
Should ON go to the last dimmer setting or 100%? Does it mean “done that, here’s where I am”?
Everyone plays by different rules here.

In this case, what you’d really like to know is the device state after it has finished processing the command. Delaying poll after command is one way to get that.
Or maybe for this dimmer it’s telling the “truth” all along, and ends up at 50%. .


(Mark) #10

This is the correct way to solve this issue. Some devices, such as dimmers and locks, take some time to reach their final state after being sent a command. Lengthening the command repoll interval prevents the binding from polling for the new state while the device is still transitioning from the old state to the new state.

Note that some devices automatically report their state at the end of the transition to the new state. If the device automatically reports its state at the end of the transition, you can disable the command repoll.