home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
70.11k stars 29.16k forks source link

HUE spamming error LOG: Error fetching light data: #32380

Closed Kugelfang666 closed 4 years ago

Kugelfang666 commented 4 years ago

The problem

Since updating from 0.105.X to 0.106.1 my log becomes spammed with errors. All hue related items become briefly unavailable in Lovelace and then come back. This is true for all devices on both my hue bridges and always happened simultaneously for both bridges.

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

2020-02-29 09:21:33 ERROR (MainThread) [homeassistant.components.hue.light] Error fetching group data: 
2020-02-29 09:21:33 ERROR (MainThread) [homeassistant.components.hue.light] Error fetching light data: 
2020-02-29 09:14:20 ERROR (MainThread) [homeassistant.components.hue.sensor_base] Error fetching sensor data: 

Additional information

I also have the custom integration "Hue sensor advanced" running on my setup.

Mariusthvdb commented 4 years ago

many lines is your lovelace config?

well, that's is a bit weird, but I don't know, I use includes to create the Lovelace config. Is here some kind of internal setting calculating the size of the complete frontend.

unless it is the config/.storage/lovelace? But that is an older file:

Schermafbeelding 2020-03-10 om 23 42 48

I can easily test it, since my ui-lovelace.yaml looks like this:

##############################################################################################################
# Main Lovelace configuration file, calling all Views via !include lovelace/view_***
# for ease of editing the separate Views, and prevent errors while doing so to the full setup
# @mariusthvdb
##############################################################################################################

title: Ha Rpi4

resources: !include lovelace/resources.yaml
button_card_templates: !include lovelace/includes/button_card_templates.yaml
decluttering_templates: !include_dir_named lovelace/decluttering_templates
custom_header: !include lovelace/includes/custom_header.yaml
popup_cards: !include lovelace/popup_cards/popup_cards.yaml

views:
  - !include lovelace/views/view_Home.yaml                   #0
  - !include lovelace/views/view_Lights.yaml                 #1
  - !include lovelace/views/view_Ikea_tradfri.yaml           #2
  - !include lovelace/views/view_Philips_hue.yaml            #3
  - !include lovelace/views/view_Philips_hue_settings.yaml   #4 hide | dev show
  - !include lovelace/views/view_Floorplan.yaml              #5 hide
  - !include lovelace/views/view_Settings.yaml               #6
  - !include lovelace/views/view_Notify.yaml                 #7
  - !include lovelace/views/view_Alarm.yaml                  #8 hide
  - !include lovelace/views/view_Home_climate.yaml           #9 hide
  - !include lovelace/views/view_Home_summary.yaml           #10
  - !include lovelace/views/view_Summary_groups.yaml         #11 hide
  - !include lovelace/views/view_Home_assistant.yaml         #12
  - !include lovelace/views/view_Home_energy.yaml            #13 hide
  - !include lovelace/views/view_Home_solar_energy.yaml      #14 hide
  - !include lovelace/views/view_Phones_tablets.yaml         #15 hide
  - !include lovelace/views/view_Travel.yaml                 #16
  - !include lovelace/views/view_Weer_klimaat.yaml           #17
  - !include lovelace/views/view_Alarmclock.yaml             #18
  - !include lovelace/views/view_Tijd_agenda.yaml            #19
  - !include lovelace/views/view_Computer_netwerk.yaml       #20 hide
  - !include lovelace/views/view_Audio_video_gaming.yaml     #21 hide
  - !include lovelace/views/view_Media_players.yaml          #22 hide
  - !include lovelace/views/view_Developer.yaml              #23 hide | dev show
  - !include lovelace/views/view_All_automations.yaml        #24 hide | dev show
  - !include lovelace/views/view_All_lights_scenes.yaml      #25 hide | dev show
  - !include lovelace/views/view_All_switches_devices.yaml   #26 hide | dev show
  - !include lovelace/views/view_Weblinks.yaml               #27 hide
  - !include lovelace/views/view_Leftovers.yaml              #28 hide | dev show
  - !include lovelace/views/view_Test.yaml                   #29 hide
  - !include lovelace/views/view_Cast.yaml                   #30 hide | dev show |Chrome only

quick update: commenting all from tab11 to 30 makes a huge difference already! no error message yet. So glad you suggested this, it corroborates with what I have been saying for a long time now, that Lovelace is rather tasking and the Hue integration indicates that by going unavailable. (maybe not single cause, but it does help) Now how to solve that, can HA core be improved upon somehow to not cause this effect?

balloob commented 4 years ago

Marius, can you try disabling all your resources. I wonder if one of your custom cards is bashing the backend. Also, I suggest we move this to a new issue, as your Lovelace config is causing the issues here, Hue just shows up as a symptom.

balloob commented 4 years ago

Also implementing #32656 which might help .

Mariusthvdb commented 4 years ago

Let’s hope so, would that stop :

Hue just shows up as a symptom.

too?

Because even with only these couple of views these errors persist.

8EB1A656-41C0-434B-B203-9AF2E8B5943C

As a further analysis, it seems the App has even more issues connecting than desktop. App shows the cogwheel in the rightsize corner, and the lost connection popup even more frequently.

ECAC596B-D80E-4392-B623-18D7D8D91E95

Just so I am doing it your way, what would you need the title of the new issue to be, to have focus on the issue at hand? Something like 'Lovelace frontend causing Hue to show unavailable' ?

update all resources disabled: the errors persist. Hue keeps showing unavailable. Even on a single Lovelace view... So, refreshing Lovelace might invoke the Hue unavailability, it seems it is an underlying issue after all. Unless it takes a lot of the backend to display all red cards for unfound resources (because that's what's happening now with al resources disabled)

HA 106.6 meanwhile

Mariusthvdb commented 4 years ago

for ease of readability, please allow this extra post, if needed after that I'll create a new issue.

Ive been going over my Lovelace config methodically, first making it smaller and show only a single view, building up to the fuller config: no real change after all, the errors kept showing.

After that, I took up on Balloob's request to disable all resources. This helped me identify some unused but listed resources (....) but also didn't really help in deminishing the amount of errors logged.

What does seem to help is taking out the yaml config for Hue, and not allowing the groups, but ,most of all probably, the allow_unavailable. I had that enabled to, well, allow for groups and unavailable lights to show their state (filtering these with an extra 'reachable' attributes, separate discussion)

Not allowing these again (which is the default) seems to have diminished the amount of errors. I have even (accidentally) been able to refresh the Lovelace (3 dots top right corner) without the lights go unavailable or the error logged. Errors do still occur, and I havent yet heavily tested with running script etc. Which caused the errors/unavailable too. Will see.

Hope this seems a useful contribution in further analyzing the issue of Hue going Unavailable on us.

azogue commented 4 years ago

Hi @Mariusthvdb,

After that, I took up on Balloob's request to disable all resources

I see multiple Google Home devices in your screenshot, do these have access to the bulbs?

Naive question: have you tried to unplug anything with hue access (like the GHomes)? Isolating the problem is difficult, but it is crucial if we want to discover and fix the issues

Much more naive question (from my personal experience): have you tried to restart the hue hub? It seems silly but it worked for me more than once in the past.

Mariusthvdb commented 4 years ago

Well, I have tried all of that, more than once, and for a very long period already. It is all so very frustrating. In the end, I feel it boils down the fact the HA/Hue integration in its various iterations does 1 thing very consequently, namely indicate the entities (lights And sensors) unavailable way too often.

It makes the integration practically unusable for logic used on states of the lights and sensors.

Just read this, and fully realizing and appreciating this was a very long time ago, and lots and lots of hard work and effort has been put in improving the integration, the issue remains the same: https://community.home-assistant.io/t/philips-hue-integration-unreliable/3435/13?u=mariusthvdb

If only the unavailable flag wasn't pulled as often as it is done now... why would only Hue suffer from this. Have a look at the sensors the Custom integration creates, they are rock solid, and never blink an eye, (reason for me to use these as base for core logic I my setup), while the core sensors are just as flakey as the lights. I have even disabled them for now, which in my view is almost heresy.

All of this while the lights and sensors in fact are not unstable at all, and proven to be reliable and reachable, and most certainly available, in real life. And in the Hue App for that matter.

So, I can disable as many as all resources, and show only 1 view, it really is of no consequence I am afraid, how much I am willing to keep testing all of that. Just did once more.

Ill follow your efforts here, have installed the latest update already, and though working as fine as ever, I still see the errors logged, and my lights always reflect that in their last_changed field, which is how I can immediately spot what's happening:

at 22:28 I logged in with my phone (error raised all lights reset last-changed, 22:36/6 outside movement lit up the outside lights. Gym audio is an Ikea light, and solid as ever. Turned on at my scene triggers....

Schermafbeelding 2020-03-11 om 22 47 41

Sorry to be a bit sceptic, will keep trying though, and test whatever you guys throw at us. I am as adamant as you to get this solved.

ps about the Google Homes: I have tried indeed, but only using these for a short time, while the issue pre-dates that with a few years.. So it won't be it.

Kugelfang666 commented 4 years ago

so I just updated the CC to 2.14 . while I still encounter the errors in the log something has changed:

ERROR (MainThread) [homeassistant.components.hue.light] Error fetching group data: 
ERROR (MainThread) [homeassistant.components.hue.light] Error fetching light data: 
ERROR (MainThread) [homeassistant.components.hue.sensor_base] Error fetching sensor data:

Error fetching light data: 83x Error fetching group data: 84x Error fetching sensor data: 2x

before they always had the same (similar) count...

Mariusthvdb commented 4 years ago

Is it correct we still see the fetching sensor error, after having disabled all core Hue sensors in the entities tab? I would have hoped to at least stop that from causing an error logged, but it apparently doesnt..

Schermafbeelding 2020-03-12 om 17 37 45

note the timing is different, where they previously appear 3 in a row

azogue commented 4 years ago

cc @balloob,

maybe those errors should be ignored most of the times, I just discovered how easy it is to generate them, and what is happening really:

2020-03-12 18:27:02 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:02.000531+00:00
2020-03-12 18:27:03 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:03.002715+00:00
2020-03-12 18:27:04 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:04.001065+00:00
2020-03-12 18:27:06 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:06.005077+00:00
2020-03-12 18:27:07 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:07.003826+00:00
2020-03-12 18:27:08 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:08.000978+00:00
2020-03-12 18:27:09 ERROR (MainThread) [homeassistant.components.hue.sensor_base] Timeout fetching sensor data
2020-03-12 18:27:09 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:05.000542+00:00
2020-03-12 18:27:09 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:09.000580+00:00
2020-03-12 18:27:10 DEBUG (MainThread) [custom_components.huesensor.remote] Update requested at 2020-03-12 17:27:10.004379+00:00

IMHO we could totally ignore (or at least decrease the log level) these request errors in those situations, and only log 'real bridge disconnects' (> timeout without success). I imagine that A LOT of them would disappear.

balloob commented 4 years ago

Requesting an update is not actually updating the data.

Mariusthvdb commented 4 years ago

@azogue wrote:

only log 'real bridge disconnects'

Yes, that would be something most of the HA community Hue users ask for, since a very long time indeed... just one of the many posts on the unavailability Btw, for your info: this is when it all started....

azogue commented 4 years ago

Requesting an update is not actually updating the data.

I know, but I was talking about checking if another call does the update request successfully while the current failed one gets the timeout exception. It is better to show it: #32751

Mariusthvdb commented 4 years ago

Marius, can you try disabling all your resources. I wonder if one of your custom cards is bashing the backend.

I did find 1 card to cause definite trouble in the end. Not saying taking it out solves all errors, but having this on my test page along with some nifty Hue lights auto rendering:

  - type: custom:auto-entities
    card:
      type: entities
      title: Multiple lights
#      show_header_toggle: false
    show_empty: false
    filter:
      include:
        - domain: light
          state: 'on'
          attributes:
            rgb_color: '! none'
          options:
             type: custom:multiple-entity-row
             toggle: true
             secondary_info: last-changed
             entities:
               - entity: this.entity_id
                 attribute: brightness
                 name: Bri
                 unit: '%'
               - entity: this.entity_id
                 attribute: rgb_color
                 name: Rgb

causes these lights to constantly go unavailable. Not sure if it is the Lovelace page, or the backend causing timing issues or what have you, but still, for reference reporting it here:

#      - type: iframe
#        style: |
#          ha-card {
#            overflow: hidden;
#            padding: 0px;
#          }
#        aspect_ratio: 90%
#        url: https://gadgets.buienradar.nl/gadget/zoommap/?lat=5xxx3&lng=4.xxx&overname=2&zoom=13&naam=City&size=3b&voor=1

didn't make a difference if I took out styling or not, is was the buienradar iframe gadget causing trouble.

qJake commented 4 years ago

Just wanted to chime in, I'm having the same issue. It's quite annoying when my Hue integration is "Unavailable" quite often during a 24h period, example:

image

I have one Hue v2 bridge and about 20 bulbs. No third party stuff, no other Philips products like blooms or strips or anything like that.

These are the errors I'm seeing, in chronological order (oldest first).


Log Details (ERROR)

Logger: homeassistant.components.hue.sensor_base Source: helpers/update_coordinator.py:126 Integration: hue First occurred: 8:23:04 PM (1 occurrences) Last logged: 8:23:04 PM

Error requesting sensor data: None

Log Details (ERROR)

Logger: homeassistant.components.hue.light Source: helpers/update_coordinator.py:126 Integration: hue First occurred: 8:23:00 PM (2 occurrences) Last logged: 8:23:04 PM


Log Details (ERROR)

Logger: homeassistant.components.hue.bridge Source: components/hue/bridge.py:131 Integration: hue First occurred: 8:23:00 PM (4 occurrences) Last logged: 8:23:07 PM

Request failed 3 times, giving up.
atechnical commented 4 years ago

Same issue on Home Assistant 0.108.3 Errors in chronological order below. I am using a Conbee 2 to integrate some Sengled bulbs if it matters.

Log Details (ERROR) Logger: homeassistant.components.hue.bridge Source: components/hue/bridge.py:131 Integration: hue (documentation, issues) First occurred: 8:17:00 PM (82 occurrences) Last logged: 10:28:06 PM

Request failed 3 times, giving up.

Log Details (ERROR) Logger: homeassistant.components.hue.light Source: helpers/update_coordinator.py:133 Integration: hue (documentation, issues) First occurred: 8:16:28 PM (13 occurrences) Last logged: 10:27:13 PM

Timeout fetching light data

Log Details (ERROR) Logger: homeassistant.components.hue.sensor_base Source: helpers/update_coordinator.py:133 Integration: hue (documentation, issues) First occurred: 8:16:24 PM (13 occurrences) Last logged: 10:27:13 PM

Timeout fetching sensor data

Logger: homeassistant.core Source: components/hue/bridge.py:124 First occurred: 8:17:00 PM (2 occurrences) Last logged: 8:17:01 PM

Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 936, in _wrap_create_connection return await self._loop.create_connection(*args, **kwargs) # type: ignore # noqa File "/usr/local/lib/python3.7/asyncio/base_events.py", line 962, in create_connection raise exceptions[0] File "/usr/local/lib/python3.7/asyncio/base_events.py", line 949, in create_connection await self.sock_connect(sock, address) File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 473, in sock_connect return await fut File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 503, in _sock_connect_cb raise OSError(err, f'Connect call failed {address}') ConnectionRefusedError: [Errno 111] Connect call failed ('192.168.1.121', 80)

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/core.py", line 1255, in _execute_service await handler.func(service_call) File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service self._platforms.values(), func, call, required_features File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 412, in entity_service_call future.result() # pop exception if have File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 600, in async_request_call await coro File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 443, in _handle_entity_call await result File "/usr/src/homeassistant/homeassistant/components/light/init.py", line 243, in async_handle_light_on_service await light.async_turn_on(params) File "/usr/src/homeassistant/homeassistant/components/hue/light.py", line 399, in async_turn_on partial(self.light.set_state, command) File "/usr/src/homeassistant/homeassistant/components/hue/bridge.py", line 124, in async_request_call return await task() File "/usr/local/lib/python3.7/site-packages/aiohue/lights.py", line 117, in set_state json=data) File "/usr/local/lib/python3.7/site-packages/aiohue/bridge.py", line 63, in request async with self.websession.request(method, url, json=json) as res: File "/usr/local/lib/python3.7/site-packages/aiohttp/client.py", line 1012, in aenter self._resp = await self._coro File "/usr/local/lib/python3.7/site-packages/aiohttp/client.py", line 483, in _request timeout=real_timeout File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 523, in connect proto = await self._create_connection(req, traces, timeout) File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 859, in _create_connection req, traces, timeout) File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 1004, in _create_direct_connection raise last_exc File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 986, in _create_direct_connection req=req, client_error=client_error) File "/usr/local/lib/python3.7/site-packages/aiohttp/connector.py", line 943, in _wrap_create_connection raise client_error(req.connection_key, exc) from exc aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host 192.168.1.121:80 ssl:None [Connect call failed ('192.168.1.121', 80)]

qJake commented 4 years ago

0.108.5, still experiencing, but (at least for the past 24 hours) seems to be a little better:

image

Not sure why it's so random/sporadic.

geekofweek commented 4 years ago

I was fighting this issue as well and did all kinds of troubleshooting. What I discovered was my Hue Hub was rebooting at regular intervals whenever it went offline in HA, which was about every hour. That meant it wasn't just HA that couldn't interact it was everything.

After a lot of digging what I discovered was that because I had the Hue Hub on another VLAN and mDNS reflecting on it was causing the Hue Hub to get overwhelmed and crash. I use all ubiquiti networks unifi equipment and this seems to be a well reported issue that happens with the Hue Hub. Moving to the mDNS repeater over the mDNS reflector immediately resolved the issue.

This probably won't help everyone, but it might help anyone with a similar setup.

atechnical commented 4 years ago

I also have Ubiquiti with VLANS and mdns. It's way more than I need and I'm still learning how to use it. Can you explain how you ..."Moving to the mDNS repeater over the mDNS reflector"? Thanks very much.

geekofweek commented 4 years ago

This is a good forum post to get started. The short of it is you need to disable mDNS reflecting in the GUI and modify the config.gateway.json file on the controller. There is no GUI option for it and does not work on the Dream Machine line.

qJake commented 4 years ago

I have a traditional single-mask LAN (192.168.0.*) and both my hub and the VM host that Home Assistant runs on are hard-wired (via the same switch) to the same router.

If my Hue Hub is in fact rebooting... how/where would I be able to tell this information?

xeophin commented 4 years ago

Seeing that the update_coordinator pops up in the error logs, it may be related to #33866?

Kugelfang666 commented 4 years ago

so I fully removed the CC in my setup. Moving forward im using the newly released events for the hue buttons. Unfortunately I still keep getting a lot of these Timeout fetching light data. Since I'm not using any special mDNS server or something I still wonder what might be causing this issue...

Mariusthvdb commented 4 years ago

happy to report here, that apart from the issue at startup, the errors have completely gone..

did an update to 108.x, after which Hue became fully stable. What I also did was update the custom button card to version 3.3.0 +, which prevents updating all entities configured, and only updates changed entities.

Lastly, and I haven't tested this 100%, was to exclude the light domain in recorder/history. Will enable that shorty to see if the error spamming will return.

All of this is with all Hue core sensors and lights (had sensors disabled before because they too became 'unavailable' all the time), and now even the Hue with events.

Goes without saying I only report here without any CC installed.

Can report that installing CC eventsensor by @azogue works very fine indeed, and does Not cause any harm.

All in all, happy camper here. #fingerscrossed...

Kugelfang666 commented 4 years ago

@Mariusthvdb

thanks for this! I can confirm removing the light domain from the recorder seems to have solved the issue for me!! This for me seems to be the actual solution after removing CCs and so one did not work!

Mariusthvdb commented 4 years ago

Good to hear! If this really solves it, I wish I had tried that some 2 years ago, ever since reporting hue going ‘unavailable’....

It would be an issue of true importance though, since of course we should be able to record our lights.

@balloob what would be your thoughts on this?

Kugelfang666 commented 4 years ago

hmmm after some initial euphony the error came back when I increased the polling interval, ill do some more systematic testing tomorrow

balloob commented 4 years ago

Wait till beta 109 hits and make sure that you make sure that you don't get any errors from integrations that do I/O in the event loop.

Kugelfang666 commented 4 years ago

for me the problem seems to be gone with 0.109! I updated yesterday and ever since not a single entry occurred!

Kugelfang666 commented 4 years ago

updating the OS to 4.10 brought back the problem which before was entirely solved for me :-(

Mariusthvdb commented 4 years ago

which is that (awaiting your report before updating...)?

Kugelfang666 commented 4 years ago

which is that (awaiting your report before updating...)?

Sry I don’t understand

Mariusthvdb commented 4 years ago

which is the problem that you say is brought back?

balloob commented 4 years ago

Please do not continue discussions on closed issues but open a new issue instead.