[hue] Unreliable Events from Hue Dimmer Switch

[regnets]

Parallel to my “production” setup i got a docker container with the current 2.5 Milestone Build.

I found out that lights that i control with the Philips Hue Dimmer Switch via the Milestone Build i got unreliable events from the button.

Here is the events.log part of the Build:

2019-11-01 13:47:00.658 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:04.833 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:07.944 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:18.320 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:24.549 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 1000.0
2019-11-01 13:47:42.181 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4000.0
2019-11-01 13:47:42.700 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4002.0
2019-11-01 13:48:34.549 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4000.0
2019-11-01 13:48:42.847 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4002.0
2019-11-01 13:48:49.577 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4000.0
2019-11-01 13:49:58.571 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4002.0
2019-11-01 13:53:16.717 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 1002.0
2019-11-01 13:53:25.545 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:Zigbee_Kueche_Fernbedienung:dimmer_switch_event triggered 4000.0

As you can see the Short Release events is triggered 10 seconds after the initial pressed events. sometimes i got a lot of 4000.0 events and NO 4002.0 event.

In my production setup based on the 2.4 stable version that same event from the same bridge looks like this:

2019-11-01 13:47:00.496 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1000.0
2019-11-01 13:47:01.225 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:04.707 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:07.827 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:15.110 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:18.254 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:24.483 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1000.0
2019-11-01 13:47:25.005 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:47:37.986 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:47:42.161 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4000.0
2019-11-01 13:47:42.722 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:48:12.883 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4000.0
2019-11-01 13:48:13.405 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:48:34.722 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:48:42.519 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4000.0
2019-11-01 13:48:43.043 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:48:49.817 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:49:58.554 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0
2019-11-01 13:53:16.897 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 1002.0
2019-11-01 13:53:25.755 [vent.ChannelTriggeredEvent] - hue:0820:00178827902c:kitchen:dimmer_switch_event triggered 4002.0

Basically i am missing a lot of *002.0 events or they got send much too late.

Should i open an issue on github for this?

The openhab.log file looks clean during this time period.

Here are some hints by cweitkamp of the root cause of this issue:
https://community.openhab.org/t/unreliable-philips-hue-dimmer-switch-events-with-current-2-5-milestone-m4-build/84650/19?u=regnets

[kaikreuzer]

Should i open an issue on github for this?

You just did, but yes ;-)

Here are some hints by cweitkamp of the root cause

Hm, I only read "probably cause by the polling strategy implemented in the binding" and I am not aware that anything has changed about the polling strategy since 2.4, so I am not sure, what can cause problems on 2.5, which weren't there on 2.4.
@cweitkamp As you already looked into it briefly, do you have any input on what you think could have caused a regression?

[cweitkamp]

I jumped into the code quikly and just wanted to set-up a the Hue binding, connection to the Hue Bridge and a Hue Dimmer Switch in my Eclipse IDE. I enabled TRACE logging for the binding. I linked the dimmer_switch channel to an Item and wrote a small test rule to compare the Trigger Channel Events to the State Change Events.

rule "Philips Hue Dimmer Switch - Trigger"
when
    Channel "hue:0820:XXXX:21:dimmer_switch_event" triggered
then
    logInfo("remote.control", "Philips Hue Dimmer Switch - Trigger: '{}'", receivedEvent)
end

rule "Philips Hue Dimmer Switch - State"
when
    Item hue_0820_XXXX_21_dimmer_switch changed
then
    logInfo("remote.control", "Philips Hue Dimmer Switch - State: '{}'", newState)
end

After starting OH2 from the IDE and pressing a button on the remote my log went mad and the IDE crashed. Log output looks like this - there certainly is a bug - lets see how far I can get:

...
20:47:02.213 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.213 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.214 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.214 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.215 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.215 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.216 [ngLinkManager-2] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.217 [ngLinkManager-5] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.217 [ngLinkManager-3] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.217 [ngLinkManager-4] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.217 [ngLinkManager-1] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.218 [ngLinkManager-4] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.219 [ngLinkManager-4] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.219 [ngLinkManager-4] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
20:47:02.220 [ngLinkManager-2] TRACE o.o.b.h.i.handler.HueSensorHandler:232 - onSensorStateChanged() was called
...

[cweitkamp]

I proposed a fix for the missing events in #6579 which ensures that every event we will receive from the hue API will be forwarded towards the framework.

BUT I have to add a note on this: The hue API issues one event per second (at maximum). Meaning if you are capable of pressing the button of your remote more than once per second even the hue API will miss those events and we cannot emit them either.