Still experiencing Hue state update issues after 2021.12.4

robertoash commented 2 years ago

The problem

I am still experiencing two types of issues regarding state updating for Hue lights even after upgrading to 2021.12.4:

Service call works but no change in HA UI. The correct status is showing in the Hue App. A reload of the integration resyncs status to correct values.
When toggling lights from the UI, here's what happens:
- Turn on in HA --> Light turns on --> HA jumps back automatically to off but light stays on (end result: HA=off, Light = on)
- After this, to fix the sync, you have to Turn on in HA and QUICKLY turn off in HA. Light turns off. No jump back. (end result: HA=off, Light = off)
- Same thing applies to if HA is on and light is also on. Turn off HA --> Light turns off --> HA jumps back to on. Light still off.

What version of Home Assistant Core has the issue?

core-2021.12.4

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Philips Hue

Link to integration documentation on our website

https://www.home-assistant.io/integrations/hue/

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No Hue related errors that I can see. I did have some 'NoneType' errors before but those seem to have disappeared after upgrading to 2021.12.4.

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

Hey there @balloob, @marcelveldt, mind taking a look at this issue as it has been labeled with an integration (hue) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

hue documentation hue source _{^{(message by IssueLinks)}}

askthomas commented 2 years ago

I have same issue, is started with 2021.12.x version.

it show also wrong info about current state, ligth is on, but off in hass. If then click twice in hass, of, then off, is turns off lamp.

Status in tuya app works, so the communacation between has and tuya, i guess the problem is.

/T

robertoash commented 2 years ago

My problem is with the Hue integration but I've also seen it happening with Deconz and Tuya (migrated to LocalTuya because of same issue and now it's not happening anymore). Maybe that's a clue into what could be going wrong?

nagubal commented 2 years ago

I am seeing the same issue with only Philips Hue branded lights, with no errors found in the logs. Edit: the lights states is correct in the Hue app

robertoash commented 2 years ago

Here's a video of the bug, in case it helps: https://user-images.githubusercontent.com/42000824/146982729-f620085e-6bf0-4069-aadb-2f700b3b26d4.mp4

marcelveldt commented 2 years ago

Sounds like your setup isn't receiving any events from the bridge of state changes. Do you have some advanced network setup maybe where the bridge resides outside the local network in a IoT lan or something ?

The EventStream (the thing that streams state events from Hue to HA) gets reconnected once it didn't receive a message within 30 minutes. So my question is, does the issue auto correct itself ?

Maybe enable debug logging for both homeassistant.components.hue and aiohue That way you can see in your log what is happening. You should see a "received status blah for entity blah" in your log as soon as you perform an action.

robertoash commented 2 years ago

Thank you for helping out!

Sounds like your setup isn't receiving any events from the bridge of state changes. Do you have some advanced network setup maybe where the bridge resides outside the local network in a IoT lan or something ?

Nope. Super simple mesh router setup with a single LAN, all under the same subnet and one DHCP server.

The EventStream (the thing that streams state events from Hue to HA) gets reconnected once it didn't receive a message within 30 minutes. So my question is, does the issue auto correct itself ?

Yes. It appears that the issue auto corrects itself after a while. At some point all lights resync to the right status but there seems to be a zone in between "all working fine" and "auto correct" where the bug is present. It is a matter of luck whether you end up in that zone or not when trying to toggle a light. However, it is most notable when trying to debug automations since you wait for the automation to trigger and expect to see the intended result in the UI but you get no change. You don't know if the automation failed or if it's a state update issue until you go and check the actual light.

Maybe enable debug logging for both homeassistant.components.hue and aiohue That way you can see in your log what is happening. You should see a "received status blah for entity blah" in your log as soon as you perform an action.

I did some tests and got the logging for them. Here's what you'll find below:

Restarted HA
22:39 --> Just after the restart, toggled some lights and everything is running as expected and status updates are being received.
23:05 --> Tried to toggle the lights again but hit the same bug. The state jumped back to "on" even though the light turned off. Even though the lamp actually turned off, there are no logs for those changes.
23:10:58 --> Reconnected to EventStream
23:11 --> Everything is working as expected again

2021-12-21 22:39:21 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_2
2021-12-21 22:39:22 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_1
2021-12-21 22:39:22 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_3
2021-12-21 22:39:26 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_2
2021-12-21 22:39:27 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_1
2021-12-21 22:39:27 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_3
2021-12-21 22:39:32 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_color_lamp
2021-12-21 22:39:42 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_color_lamp
2021-12-21 22:40:00 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.dining_room_lamp
2021-12-21 22:40:05 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.dining_room_lamp
2021-12-21 22:40:12 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:40:20 ERROR (MainThread) [homeassistant.components.hassio.handler] /ingress/validate_session return code 401
2021-12-21 22:40:20 ERROR (MainThread) [homeassistant.components.hassio] Failed to to call /ingress/validate_session -
2021-12-21 22:40:20 ERROR (MainThread) [homeassistant.components.hassio.handler] /ingress/validate_session return code 401
2021-12-21 22:40:20 ERROR (MainThread) [homeassistant.components.hassio] Failed to to call /ingress/validate_session -
2021-12-21 22:40:56 DEBUG (MainThread) [homeassistant.components.hue.bridge.device_power] Received status update for sensor.dining_room_switch_battery
2021-12-21 22:41:13 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:42:12 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [548205695568] Connection closed by client
2021-12-21 22:42:12 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [548206445712] Connection closed by client
2021-12-21 22:42:13 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:43:14 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:44:14 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:45:15 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:46:15 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:47:16 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:48:16 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:49:17 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:50:18 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:51:18 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:52:19 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:53:19 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:53:58 WARNING (Thread-9) [pychromecast.socket_client] [Bedroom speaker(192.168.1.133):8009] Heartbeat timeout, resetting connection
2021-12-21 22:53:58 INFO (Thread-9) [pychromecast.controllers] Receiver:channel_disconnected
2021-12-21 22:53:58 INFO (Thread-9) [pychromecast.socket_client] [Bedroom speaker(192.168.1.133):8009] Connection reestablished!
2021-12-21 22:53:58 WARNING (Thread-10) [pychromecast.socket_client] [Anna's Office speaker(192.168.1.182):8009] Heartbeat timeout, resetting connection
2021-12-21 22:53:58 INFO (Thread-10) [pychromecast.controllers] Receiver:channel_disconnected
2021-12-21 22:53:58 INFO (Thread-10) [pychromecast.socket_client] [Anna's Office speaker(192.168.1.182):8009] Connection reestablished!
2021-12-21 22:53:59 WARNING (Thread-8) [pychromecast.socket_client] [Rob's Office speaker(192.168.1.234):8009] Heartbeat timeout, resetting connection
2021-12-21 22:53:59 INFO (Thread-8) [pychromecast.controllers] Receiver:channel_disconnected
2021-12-21 22:53:59 INFO (Thread-8) [pychromecast.socket_client] [Rob's Office speaker(192.168.1.234):8009] Connection reestablished!
2021-12-21 22:54:20 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:55:20 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:55:45 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.tv_room_audio_input_format fails
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 174, in _new_conn
conn = connection.create_connection(
File "/usr/local/lib/python3.9/site-packages/urllib3/util/connection.py", line 96, in create_connection
raise err
File "/usr/local/lib/python3.9/site-packages/urllib3/util/connection.py", line 86, in create_connection
sock.connect(sa)
socket.timeout: timed out
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 699, in urlopen
httplib_response = self._make_request(
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 394, in _make_request
conn.request(method, url, **httplib_request_kw)
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 239, in request
super(HTTPConnection, self).request(method, url, body=body, headers=headers)
File "/usr/local/lib/python3.9/http/client.py", line 1279, in request
self._send_request(method, url, body, headers, encode_chunked)
File "/usr/local/lib/python3.9/http/client.py", line 1325, in _send_request
self.endheaders(body, encode_chunked=encode_chunked)
File "/usr/local/lib/python3.9/http/client.py", line 1274, in endheaders
self._send_output(message_body, encode_chunked=encode_chunked)
File "/usr/local/lib/python3.9/http/client.py", line 1034, in _send_output
self.send(msg)
File "/usr/local/lib/python3.9/http/client.py", line 974, in send
self.connect()
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 205, in connect
conn = self._new_conn()
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 179, in _new_conn
raise ConnectTimeoutError(
urllib3.exceptions.ConnectTimeoutError: (<urllib3.connection.HTTPConnection object at 0x7f97d7a670>, 'Connection to 192.168.1.245 timed out. (connect timeout=5)')
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/requests/adapters.py", line 439, in send
resp = conn.urlopen(
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 755, in urlopen
retries = retries.increment(
File "/usr/local/lib/python3.9/site-packages/urllib3/util/retry.py", line 574, in increment
raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='192.168.1.245', port=1400): Max retries exceeded with url: /DeviceProperties/Control (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f97d7a670>, 'Connection to 192.168.1.245 timed out. (connect timeout=5)'))
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 487, in async_update_ha_state
await self.async_device_update()
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 691, in async_device_update
raise exc
File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
result = self.fn(*self.args, **self.kwargs)
File "/usr/src/homeassistant/homeassistant/components/sonos/sensor.py", line 89, in update
self._attr_native_value = self.soco.soundbar_audio_input_format
File "/usr/local/lib/python3.9/site-packages/soco/core.py", line 1270, in soundbar_audio_input_format
format_code = self.soundbar_audio_input_format_code
File "/usr/local/lib/python3.9/site-packages/soco/core.py", line 1240, in soundbar_audio_input_format_code
response = self.deviceProperties.GetZoneInfo()
File "/usr/local/lib/python3.9/site-packages/soco/services.py", line 207, in _dispatcher
return self.send_command(action, *args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/soco/services.py", line 481, in send_command
response = requests.post(
File "/usr/local/lib/python3.9/site-packages/requests/api.py", line 117, in post
return request('post', url, data=data, json=json, **kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/api.py", line 61, in request
return session.request(method=method, url=url, **kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/sessions.py", line 542, in request
resp = self.send(prep, **send_kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/sessions.py", line 655, in send
r = adapter.send(request, **kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/adapters.py", line 504, in send
raise ConnectTimeout(e, request=request)
requests.exceptions.ConnectTimeout: HTTPConnectionPool(host='192.168.1.245', port=1400): Max retries exceeded with url: /DeviceProperties/Control (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f97d7a670>, 'Connection to 192.168.1.245 timed out. (connect timeout=5)'))
2021-12-21 22:55:49 WARNING (Thread-9) [pychromecast.socket_client] [Bedroom speaker(192.168.1.133):8009] Heartbeat timeout, resetting connection
2021-12-21 22:55:49 INFO (Thread-9) [pychromecast.controllers] Receiver:channel_disconnected
2021-12-21 22:55:49 WARNING (Thread-10) [pychromecast.socket_client] [Anna's Office speaker(192.168.1.182):8009] Heartbeat timeout, resetting connection
2021-12-21 22:55:49 INFO (Thread-10) [pychromecast.controllers] Receiver:channel_disconnected
2021-12-21 22:55:49 WARNING (Thread-8) [pychromecast.socket_client] [Rob's Office speaker(192.168.1.234):8009] Heartbeat timeout, resetting connection
2021-12-21 22:55:49 INFO (Thread-8) [pychromecast.controllers] Receiver:channel_disconnected
2021-12-21 22:55:56 INFO (Thread-9) [pychromecast.socket_client] [Bedroom speaker(192.168.1.133):8009] Connection reestablished!
2021-12-21 22:55:57 INFO (Thread-8) [pychromecast.socket_client] [Rob's Office speaker(192.168.1.234):8009] Connection reestablished!
2021-12-21 22:55:57 INFO (Thread-10) [pychromecast.socket_client] [Anna's Office speaker(192.168.1.182):8009] Connection reestablished!
2021-12-21 22:56:21 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:57:21 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:58:22 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 22:59:23 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:00:23 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:01:24 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:02:24 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:03:25 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:04:25 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:05:10 INFO (Recorder) [homeassistant.components.sensor.recorder] Detected new cycle for sensor.tv_energy_hourly, value dropped from 0.041 to 2021-12-21T22:00:00.554041+00:00, triggered by state with last_updated set to 0.0
2021-12-21 23:05:26 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:06:27 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:07:20 ERROR (MainThread) [homeassistant.components.tplink.coordinator] Error fetching 192.168.1.166 data: Unable to connect to the device: 192.168.1.166
2021-12-21 23:07:27 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:08:28 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:09:28 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:10:29 INFO (MainThread) [volvooncall.volvooncall] Updating
2021-12-21 23:10:43 INFO (MainThread) [homeassistant.components.tplink.coordinator] Fetching 192.168.1.166 data recovered
2021-12-21 23:10:56 DEBUG (MainThread) [aiohue.v2[192.168.1.155].events] Disconnected from EventStream - Reconnect will be attempted in 2 seconds
2021-12-21 23:10:58 DEBUG (MainThread) [aiohue.v2[192.168.1.155].events] Connected to EventStream
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].bridge] fetched 1 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].bridge_home] fetched 1 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].entertainment] fetched 6 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].entertainment_configuration] fetched 0 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].device] fetched 11 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].light] fetched 9 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].scene] fetched 50 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].button] fetched 4 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].device_power] fetched 1 items
2021-12-21 23:10:59 DEBUG (MainThread) [homeassistant.components.hue.bridge.device_power] Received status update for sensor.dining_room_switch_battery
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].geofence_client] fetched 0 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].light_level] fetched 0 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].motion] fetched 0 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].temperature] fetched 0 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].zigbee_connectivity] fetched 11 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].room] fetched 5 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].zone] fetched 0 items
2021-12-21 23:10:59 DEBUG (MainThread) [aiohue.v2[192.168.1.155].grouped_light] fetched 5 items
2021-12-21 23:11:09 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_color_lamp
2021-12-21 23:11:10 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_color_lamp
2021-12-21 23:11:13 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_2
2021-12-21 23:11:14 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_1
2021-12-21 23:11:14 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_bulb_3
2021-12-21 23:11:22 DEBUG (MainThread) [homeassistant.components.hue.bridge.light] Received status update for light.tv_room_color_lamp

marcelveldt commented 2 years ago

Thanks for the detailed answer, it helps us in debugging the issue! OK, so the auto reconnect logic is actually working but what is causing it to fail is the million dollar question. Looking at your log it seems that there's a lot more that is disconnected and/or reconnected at more or less the same timestamp. Maybe there's a clue in there...

Anyways, we're investigating the issue and we'll keep you posted. Hopefully we can provide a fix soon. Thanks!

danielzrob commented 2 years ago

I'm also having this issue with Hue, and as commented Tuya too. I will keep an eye on this thread and report back if any recommendations are made.

Scope666 commented 2 years ago

This fixed the status updates for me on the Tuya side, I haven't really noticed it much with Hue.

https://github.com/home-assistant/core/issues/62408#issuecomment-999648277

danielzrob commented 2 years ago

Thanks !!!

danielzrob commented 2 years ago

Got the Tuya patch all installed and working well!

However I think I am clearly missing something in the Hue fix. I attempted to patch it but I think what it is calling on "BridgeBusy" is not importing correctly. I'm not sure if is simply a lib I do not have locally or I am screwing something up. Likely both.

For now I will look around for others with a similar issue and see if they were more effective with the patch than I.

marcelveldt commented 2 years ago

@danielzrob This issue is about the Hue integration, not Tuya, you did notice that ?

danielzrob commented 2 years ago

@danielzrob This issue is about the Hue integration, not Tuya, you did notice that ?

Several posts in the thread spoke on both integrations, as promised, I applied and responded with my results. Also as noted I am still having state issues with Hue.

marcelveldt commented 2 years ago

Can you please open a new issuereport for the issues you're experiencing with Hue ? Thanks!

home-assistant / core