Intermittent toggling between states of certain lights

[VF-mbrauer]

Issue

I've seen a strange issue when using HUE Wall Switches, Sometimes I see that the HUE Lights develop a life of their own.
So, in specific circumstances turning OFF lights via the Switch, 5 lights go off as they should, and then 1 or 2 go back on.

Details:

1. [27/10/2023, 07:51:30] [Hue-Bridge] SWI - Spots NEW Rocker 2 should turn OFF the Light Spot Colored [1-5]
2. [27/10/2023, 07:51:31] [Hue-Bridge] Light Spot Colored [1-5] changed the state from TRUE to FALSE
3. [27/10/2023, 07:51:34] [Hue-Bridge] Light Spot Colored 2 set state from false to true due to whatever reason
4. [27/10/2023, 07:51:38] [Hue-Bridge] SWI - Spots NEW Rocker 2: another tries to Turn the colored lights off
5. [27/10/2023, 07:51:38] [Hue-Bridge] Light Spot Colored 2 changed from TRUE to FALSE

This issue is not permanent, seems that we need to check some Race conditions.

Log Messages

[27/10/2023, 07:35:29] [Hue-Bridge] Hue temperature sensor 1: set homekit temperature from 20.5°C to 20.7°C
[27/10/2023, 07:38:35] [Hue-Bridge] Light Shower: set homekit brightness from 100% to 50%
[27/10/2023, 07:38:36] [Hue-Bridge] Light Shower: set homekit brightness from 50% to 85%
[27/10/2023, 07:38:37] [Hue-Bridge] Sensor Shower: set homekit motion from 0 to 1
[27/10/2023, 07:38:39] [Hue-Bridge] presenceState: set homekit status from 3 to 4
[27/10/2023, 07:38:53] [Hue-Bridge] Light Shower: set homekit brightness from 85% to 50%
[27/10/2023, 07:39:19] [Hue-Bridge] Sensor Shower: set homekit motion from 1 to 0
[27/10/2023, 07:39:25] [Hue-Bridge] Hue ambient light sensor 1: set homekit light level from 164.7783 lux to 115.5048 lux
[27/10/2023, 07:42:04] [Hue-Bridge] Sensor Shower: set homekit motion from 0 to 1
[27/10/2023, 07:42:33] [Hue-Bridge] Sensor Shower: set homekit motion from 1 to 0
[27/10/2023, 07:44:24] [Hue-Bridge] Hue ambient light sensor 1: set homekit light level from 115.5048 lux to 118.2497 lux
[27/10/2023, 07:46:49] [Hue-Bridge] Light Shower: set homekit brightness from 50% to 0%
[27/10/2023, 07:46:49] [Hue-Bridge] Light Shower: set homekit brightness from 0% to 1%
[27/10/2023, 07:46:56] [Hue-Bridge] Sensor Shower: set homekit motion from 0 to 1
[27/10/2023, 07:47:18] [Hue-Bridge] Sensor Shower: set homekit motion from 1 to 0
[27/10/2023, 07:49:24] [Hue-Bridge] Hue ambient light sensor 1: set homekit light level from 118.2497 lux to 99.747 lux
[27/10/2023, 07:51:28] [Hue-Bridge] SWI - Spots NEW Rocker 1: homekit button single press
[27/10/2023, 07:51:28] [Hue-Bridge] SWI - Ceiling Rocker 1: homekit button single press
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 2: homekit brightness changed from 66% to 100%
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 2: homekit on changed from false to true
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 1: homekit color temperature changed from 451 mired to 370 mired
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 3: homekit on changed from false to true
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 2: homekit color temperature changed from 451 mired to 370 mired
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 4: homekit color temperature changed from 447 mired to 370 mired
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 3: homekit brightness changed from 42% to 100%
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 5: homekit on changed from false to true
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 3: homekit color temperature changed from 451 mired to 370 mired
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 4: homekit on changed from false to true
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 4: homekit brightness changed from 74% to 100%
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 1: homekit brightness changed from 62% to 100%
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 1: homekit on changed from false to true
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 5: homekit color temperature changed from 451 mired to 370 mired
[27/10/2023, 07:51:29] [Hue-Bridge] Light Spot White 5: homekit brightness changed from 81% to 100%
[27/10/2023, 07:51:29] [Hue-Bridge] Light Ceiling: homekit on changed from true to false
[27/10/2023, 07:51:30] [Hue-Bridge] SWI - Spots NEW Rocker 2: homekit button single press
[27/10/2023, 07:51:30] [Hue-Bridge] SWI - Spots NEW Rocker 1: homekit button single press
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot Colored 5: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot Colored 4: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot Colored 2: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot Colored 3: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot Colored 1: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot White 1: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot White 2: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot White 5: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot White 3: homekit on changed from true to false
[27/10/2023, 07:51:31] [Hue-Bridge] Light Spot White 4: homekit on changed from true to false
[27/10/2023, 07:51:33] [Hue-Bridge] Light Shower: set homekit brightness from 1% to 0%
[27/10/2023, 07:51:34] [Hue-Bridge] Light Spot Colored 2: set homekit on from false to true
[27/10/2023, 07:51:35] [Hue-Bridge] SWI - Spots NEW Rocker 1: homekit button single press
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 2: homekit brightness changed from 100% to 100%
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 2: homekit on changed from false to true
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 3: homekit on changed from false to true
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 3: homekit brightness changed from 100% to 100%
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 5: homekit on changed from false to true
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 4: homekit on changed from false to true
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 4: homekit brightness changed from 100% to 100%
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 1: homekit brightness changed from 100% to 100%
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 1: homekit on changed from false to true
[27/10/2023, 07:51:35] [Hue-Bridge] Light Spot White 5: homekit brightness changed from 100% to 100%
[27/10/2023, 07:51:36] [Hue-Bridge] SWI - Spots NEW Rocker 1: homekit button single press
[27/10/2023, 07:51:36] [Hue-Bridge] Light Spot White 1: homekit on changed from true to false
[27/10/2023, 07:51:36] [Hue-Bridge] Light Spot White 2: homekit on changed from true to false
[27/10/2023, 07:51:36] [Hue-Bridge] Light Spot White 5: homekit on changed from true to false
[27/10/2023, 07:51:36] [Hue-Bridge] Light Spot White 3: homekit on changed from true to false
[27/10/2023, 07:51:36] [Hue-Bridge] Light Spot White 4: homekit on changed from true to false
[27/10/2023, 07:51:38] [Hue-Bridge] SWI - Spots NEW Rocker 2: homekit button single press
[27/10/2023, 07:51:38] [Hue-Bridge] Light Spot Colored 2: homekit on changed from true to false
[27/10/2023, 07:51:57] [Hue-Bridge] Spot Shower: homekit on changed from true to false
[27/10/2023, 07:52:18] [Hue-Bridge] Hue ambient light sensor 1: set homekit light level from 99.747 lux to 0.0001 lux
[27/10/2023, 07:52:19] [Hue-Bridge] Hue ambient light sensor 1: set homekit dark from 0 to 1

Debug Files

[ebaauw]

It looks like you’re using HomeKit automations to set the lights when the wall switch button is pressed? I strongly recommend to use Hue bridge rules recalling Hue bridge scenes instead.

1. You also pressed new rocker 1, causing 10 simultaneous API call to the Hue bridge, resulting in 10 Zigbee messages. Just before that, you pressed new rocker 1, to turn on the white spots, resulting in 10 API calls and 20-30 Zigbee messages. The Zigbee network handles max 20 messages per second. I lost track at how the gen-2 Hue bridge handles a storm of API calls, they change this between bridge firmware versions. The gen-1 Hue bridge definitely cannot handle this load. Homebridge Hue will throttle requests, but I need a debug log file to see if that’s at play.
2. Did the light 2 physically turn off and back on, or did it just remain on? I fear the light simply didn’t get the Zigbee message to turn off.
3. Homebridge Hue polls the Hue bridge, that reports spot 2 is on, and updates the state in HomeKit.
4. HomeKit is smart and sees only light 2 needs to be changed. So now only one API call and one Zigbee message.

[VF-mbrauer]

It looks like you’re using HomeKit automations to set the lights when the wall switch button is pressed? I strongly recommend to use Hue bridge rules recalling Hue bridge scenes instead.

I will lose the flexibility and the limited features in this case. Using the full fletch of things needs this way of doing. HUE is far behind with the possibilities in their own app, unfortunately.

You also pressed new rocker 1, causing 10 simultaneous API call to the Hue bridge, resulting in 10 Zigbee messages. Just before that, you pressed new rocker 1, to turn on the white spots, resulting in 10 API calls and 20-30 Zigbee messages. The Zigbee network handles max 20 messages per second. I lost track at how the gen-2 Hue bridge handles a storm of API calls, they change this between bridge firmware versions. The gen-1 Hue bridge definitely cannot handle this load. Homebridge Hue will throttle requests, but I need a debug log file to see if that’s at play.

Why is that the case that Switch send 10 simultaneous API call is that also an issue or working as designed?
And yes, the chance is higher to catch the issue when somebody presses two rockers as they want to turn off several lights.
Attached is a debug log: Toggling_case_debug.log

Use-case: I pushed on Gabriel Deckenleuchte Rocker 1 and Gabriel Spots NEW Rocker 2 and then Deckenspot Bunt 1-5 turned on and Gabriel Deckenlampe also was flashing on and then quickly turned off again.

Did the light 2 physically turn off and back on, or did it just remain on? I fear the light simply didn’t get the Zigbee message to turn off.

Yes, light 2 physically turns off and back on, kind of flashing/toggling

[ebaauw]

Why is that the case that Switch send 10 simultaneous API call is that also an issue or working as designed?

The switch doesn't send API calls; it just sends a single buttonevent message. Here is what happens:

• The switch sends a custom Zigbee message to the Hue bridge;
• The bridge sends a push notification to Homebridge Hue, with new values for buttonevent and lastupdated;
• Homebridge Hue sends a push notification to HomeKit. translating the buttonevent series 1000 (press), 1002 (release) into a Single Press;
• The home hub triggers the action on the Single Press, sending a single HAP message to Homebridge / HAPNodeJS with up to 50 new characteristic values;
• HAP-NodeJS breaks this message into up to 50 events to Homebridge Hue (these are the homekit ... changed messages);
• Homebridge Hue combines the (on/off, brightness, hue/saturation or color temperature) events for a single light into an API call to the Hue bridge (the PUT /lights/xxx/state in the log, with a body containing on, bri, and xy);
• The Hue bridge apparently acknowledges this API call immediately (the 200 OK message in the log);
• In the background, the Hue bridge translates the API call into up to three Zigbee messages (for On/Off Control, Level Control and Color Control clusters), and sends these messages to the light. As I said before, I have no visibility in how the Hue bridge queues these messages and when it sends these.

When using Hue bridge rules, this would happen;

• The switch module sends a custom Zigbee message to the Hue bridge;
• The Hue bridge triggers a rule, resulting in a single scene recall API call;
• The Hue bridge translates this call into a single (groupcast) Recall Scene Zigbee message.

[27/10/2023, 09:19:59] [Hue-Bridge] Gabriel Deckenlampe: homekit brightness changed from 100% to 100%
[27/10/2023, 09:19:59] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from false to true
[27/10/2023, 09:19:59] [Hue-Bridge] Hue Bridge: request 542: PUT /lights/5/state {"bri":254,"on":true}
[27/10/2023, 09:19:59] [Hue-Bridge] Hue Bridge: request 542: 200 OK
[27/10/2023, 09:19:59] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from true to false
[27/10/2023, 09:19:59] [Hue-Bridge] Hue Bridge: request 543: PUT /lights/5/state {"on":false}
[27/10/2023, 09:19:59] [Hue-Bridge] Hue Bridge: request 543: 200 OK

This is actually HomeKit turning the light on and off, and Homebridge Hue sending the corresponding commands to the Hue bridge. That would suggest there's something wrong in your HomeKit automations (the on and off being triggered from the same Single Press?), or the Home hub is acting up.

[VF-mbrauer]

That would suggest there's something wrong in your HomeKit automation (the on and off being triggered from the same Single Press?), or the home hub is acting up.

I checked all the rules and deactivated them for testing only the relevant ones. The issue persists.

Next to that, I also checked the communication and logs for HomeKit. Seems that there is a race condition happening when using a too-slow HomeBridge Server. I used an old Raspberry Pi for that to test my home automation setup first before I automated everything. So now I tried a Standalone Laptop with Hyper-V with a lot of Power to Handle all requests in Time.
I could not reproduce the error anymore. I will continue with testing for the next 1-2 days and come back with the results.

[VF-mbrauer]

Seems that the issue still persists with the new Hardware running HomeBridge on it. Looks like that sometimes the HUE Wall Switch sends two homekit button single press short after each other, even when pushed only one time. Can be an electrical line bruise because of other interferences on the powerlines close to the Switch.

Question: Can we enrich the HomeBridge hue-plugin in a way that we could optionally configure a delay in milliseconds so that in case we get twice a request during a specific time window one will be discarded?

Log EXAMPLE:

[10/30/2023, 3:57:03 PM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press
[10/30/2023, 3:57:03 PM] [Hue-Bridge] Gabriel Deckenlampe: homekit brightness changed from 100% to 100%
[10/30/2023, 3:57:03 PM] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from false to true
[10/30/2023, 3:57:03 PM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press
[10/30/2023, 3:57:03 PM] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from true to false

Here you see the same Trigger twice, even though pressed single time.

[ebaauw]

Looks like that sometimes the HUE Wall Switch sends two homekit button single press short after each other, even when pushed only one time. Can be an electrical line bruise because of other interferences on the powerlines close to the Switch.

The Hue wall switch doesn't know HomeKit and doesn't send Single Press events. The wall switch sends a 0x00 command from the 0xFC00 cluster, encoding the button event in the command payload. The Hue bridge translates this to an eventstream notification for buttonevent. Homebridge Hue translates that to a HomeKit Single Press.

We've had issues in the past recognosing the correct button events in Homebridge Hue, see #1148. I really need to see the debug logging to ascertain whether the Hue bridge sends duplicate events to Homebridge Hue, or whether Homebridge Hue somehow generates fake Single Press events.

Also note that the wall switch needs to be configured what type of physical switch is connected: rocker vs push. I haven't seen any bouncing effects while testing the wall switch myself, but I'm not using any in production (I think they're worthless in that they don't support dual mode and won't function without a Hue bridge or deCONZ gateway, unlike the Hue dimmer switch). If you've configured them as rocker (which the device name would suggest), I think you would see at least three events on bouncing effects. If you've configured them as push, bouncing could explain seeing two events.

Can we enrich the HomeBridge hue-plugin in a way that we could optionally configure a delay in milliseconds so that in case we get twice a request during a specific time window one will be discarded?

A debounce option? Maybe in Homebridge Hue2, but I doubt that's going to work with the mixed API v1 for polling vs API v2 for event stream. Also, I really want confirmation that, indeed, the Hue bridge is sending two events in error. I could add an option to ignore the event stream events for the wall switch module, but that would delay the triggering of Single Press in HomeKit due to polling.

[VF-mbrauer]

Here another example Debug Log

[10/31/2023, 11:35:51 AM] [Hue-Bridge] Hue Bridge: request 18818: GET /sensors
[10/31/2023, 11:35:51 AM] [Hue-Bridge] Hue Bridge: request 18818: 200 OK
[10/31/2023, 11:35:51 AM] [Hue-Bridge] Hue Bridge: request 18819: GET /lights
[10/31/2023, 11:35:51 AM] [Hue-Bridge] Hue Bridge: request 18819: 200 OK
[10/31/2023, 11:35:53 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1000,"lastupdated":"2023-10-31T10:35:53"}
[10/31/2023, 11:35:53 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1000 on 2023-10-31T10:35:53
[10/31/2023, 11:35:53 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor lastupdated changed from 2023-10-31T10:35:49 to 2023-10-31T10:35:53
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1002,"lastupdated":"2023-10-31T10:35:54"}
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1002 on 2023-10-31T10:35:54
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor lastupdated changed from 2023-10-31T10:35:53 to 2023-10-31T10:35:54
[10/31/2023, 11:35:54 AM] [Hue-Bridge] Gabriel Deckenlampe: homekit brightness changed from 100% to 100%
[10/31/2023, 11:35:54 AM] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from false to true
[10/31/2023, 11:35:55 AM] [Hue-Bridge] Hue Bridge: request 18820: PUT /lights/5/state {"bri":254,"on":true}
[10/31/2023, 11:35:55 AM] [Hue-Bridge] Hue Bridge: request 18820: 200 OK
[10/31/2023, 11:35:55 AM] [Hue-Bridge] Gabriel Deckenlampe: state changed event: {"on":true}
[10/31/2023, 11:35:55 AM] [Hue-Bridge] Deckenspot Bunt 4: state changed event: {"xy":[0.459,0.412],"ct":369}
[10/31/2023, 11:35:55 AM] [Hue-Bridge] Deckenspot Bunt 4: light xy changed from [0.4591,0.4121] to [0.459,0.412]
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18821: GET /sensors
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18821: 200 OK
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1002 on 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor lastupdated changed from 2023-10-31T10:35:54 to 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18822: GET /lights
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18822: 200 OK
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from true to false
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18823: PUT /lights/5/state {"on":false}
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18823: 200 OK
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1000,"lastupdated":"2023-10-31T10:35:56"}
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1000 on 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1002,"lastupdated":"2023-10-31T10:35:56"}
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1002 on 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Gabriel Deckenlampe: state changed event: {"on":false}
[10/31/2023, 11:35:57 AM] [Hue-Bridge] Gabriel Deckenlampe: homekit brightness changed from 100% to 100%
[10/31/2023, 11:35:57 AM] [Hue-Bridge] Gabriel Deckenlampe: homekit on changed from false to true
[10/31/2023, 11:35:57 AM] [Hue-Bridge] Hue Bridge: request 18824: PUT /lights/5/state {"bri":254,"on":true}
[10/31/2023, 11:35:57 AM] [Hue-Bridge] Hue Bridge: request 18824: 200 OK
[10/31/2023, 11:35:57 AM] [Hue-Bridge] Gabriel Deckenlampe: state changed event: {"on":true}
[10/31/2023, 11:36:01 AM] [Hue-Bridge] Deckenspot Bunt 3: state changed event: {"xy":[0.459,0.412],"ct":369}
[10/31/2023, 11:36:01 AM] [Hue-Bridge] Deckenspot Bunt 3: light xy changed from [0.4591,0.4121] to [0.459,0.412]
[10/31/2023, 11:36:01 AM] [Hue-Bridge] Hue Bridge: request 18825: GET /sensors
[10/31/2023, 11:36:01 AM] [Hue-Bridge] Hue Bridge: request 18825: 200 OK
[10/31/2023, 11:36:01 AM] [Hue-Bridge] Hue Bridge: request 18826: GET /lights
[10/31/2023, 11:36:01 AM] [Hue-Bridge] Hue Bridge: request 18826: 200 OK
[10/31/2023, 11:36:06 AM] [Hue-Bridge] Hue Bridge: request 18827: GET /sensors
[10/31/2023, 11:36:06 AM] [Hue-Bridge] Hue Bridge: request 18827: 200 OK
[10/31/2023, 11:36:06 AM] [Hue-Bridge] Hue Bridge: request 18828: GET /lights

So the Switch has been pushed only once but I see two homekit button single press:
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press

So in this case it was toggling from ON to Off and then ON

[ebaauw]

OK, this seems to be a different situation than what started this issue (where only one out of five lights would not update its state). It looks to be a variant of #1148.

I actually see two button press/release sequences, both resulting in a Single Press.

[10/31/2023, 11:35:53 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1000,"lastupdated":"2023-10-31T10:35:53"}
[10/31/2023, 11:35:53 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1000 on 2023-10-31T10:35:53
[10/31/2023, 11:35:53 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor lastupdated changed from 2023-10-31T10:35:49 to 2023-10-31T10:35:53
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1002,"lastupdated":"2023-10-31T10:35:54"}
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1002 on 2023-10-31T10:35:54
[10/31/2023, 11:35:54 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press

and

[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1000,"lastupdated":"2023-10-31T10:35:56"}
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1000 on 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: state changed event: {"buttonevent":1002,"lastupdated":"2023-10-31T10:35:56"}
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1002 on 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press

However, when Homebridge Hue polls the Hue bridge in between these two press/release sequences, it also generates a Single Press:

[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18821: GET /sensors
[10/31/2023, 11:35:56 AM] [Hue-Bridge] Hue Bridge: request 18821: 200 OK
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte: sensor buttonevent 1002 on 2023-10-31T10:35:56
[10/31/2023, 11:35:56 AM] [Hue-Bridge] SWI - Gabriel Deckenleuchte Rocker 1: homekit button single press

I think in this case, unlike #1148, the v1 API has already been updated with the second press/release, before the event stream from the v2 API has reported this. In the other issue, the v1 API would be updated after the v2 API event stream had already reported the event.

I fear the idea of combining the v2 API event stream with v1 API polling (as fallback) doesn't work out for switches. Homebridge Hue should probably use either, but not both. For the gen-1 Hue bridges (and for gen-2 Hue bridges with really old firmware), we need to use polling (since they don't support the v2 API). Looking at the amount of hacks and failed attempts to get the buttonevent changes from the event stream, I think I'd better ignore the event stream for swiches altogether. At least until Homebridge Hue2, that will use the v2 API exclusively.

[VF-mbrauer]

I fear the idea of combining the v2 API event stream with v1 API polling (as fallback) doesn't work out for switches. Homebridge Hue should probably use either, but not both. For the gen-1 Hue bridges (and for gen-2 Hue bridges with really old firmware), we need to use polling (since they don't support the v2 API). Looking at the amount of hacks and failed attempts to get the buttonevent changes from the event stream, I think I'd better ignore the event stream for swiches altogether. At least until Homebridge Hue2, that will use the v2 API exclusively.

Just as a side note, I also have the HomeBridge system running with HUE Motion Sensors. Also, this is completely controlled by HomeKit automation as I do for Hue Wall Switch. But I have not seen one single Flapping/toggling issue.

So, it looks like that it only happens, as you also mention, for the Switches and not for other components.
Let me know when you will release a patch/fix to test. Thanks.

[ebaauw]

v0.13.68 should use the event stream exclusively for buttonevent and rotaryevent updates, on Hue bridges supporting the API v2, ignoring the values from API v1 polling. Also now using the full ms resolution of the lastupdated value in the event. On older Hue bridges, polling is used (exclusively).

I tested this with a Hue tap dial switch and a heartrate setting of 2 and it seems to work. I was able to reproduce the issue of duplicate Single Press events with the previous version in this setup.

Caveat: in case the event stream would fail, there's no longer a fallback to polling (for buttonevent and rotaryevent). I haven't seen any issues with the event stream failing, though.

Off topic, but interesting: when holding a button, then (long) releasing and press/holding it again, the event stream issues initial_press, repeat, ..., repeat, long_release, initial_press, long_press, repeat, ..., repeat, long_release. Afaik this is the only scenario where the long_press (x004) event is issued. Luckily Homebridge Hue ignores this event.

[VF-mbrauer]

It works! Awesome. I did a regression test and could not reproduce it anymore. I have also the feeling that the reaction time has decreased, which is extraordinarily positive. Lights are faster in changing their status. Not sure if that's also caused by the change. But much better user experience.

I will further test over the course of the next few days and keep an eye on anything that diverts from successful work.
Please keep this issue open for some time.

Fantastic Job. Thanks Erik.

[ebaauw]

There's nothing in the change that would affect the reaction time, but no longer getting shadow button presses would result in fewer Zigbee messages and less throttling.