0.113.2 - Home Assistant is starting, not everything will be available until it is finished.

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

71.03k stars 29.68k forks source link

0.113.2 - Home Assistant is starting, not everything will be available until it is finished. #38274

Closed deftdawg closed 4 years ago

deftdawg commented 4 years ago

The problem

Home Assistant is starting, not everything will be available until it is finished. This message persists despite home-assistant being started for over 4 hours:

4df9771ddee4        homeassistant/qemux86-64-homeassistant:0.113.1   "/init"                  24 hours ago        Up 4 hours                                                                               homeassistant

Something is getting stuck during startup and Home Assistant cannot official complete startup (see additional info for reasons I believe that)

Environment

Home Assistant Core release with the issue: 0.113.1
Last working Home Assistant Core release (if known): 0.112.x
Operating environment (OS/Container/Supervised/Core): Linux/Docker/HASSIO
Integration causing this issue: ???
Link to integration documentation on our website: N/A

Problem-relevant `configuration.yaml`

I don't know if there is a specific section of configuration that applied to this...

Traceback/Error logs

There's nothing specific I can see from the logs, if someone wants to suggest things to filter or grep for, I'm happy to do that.

Additional information

Since updating to 0.113.1:

ZWave integration doesn't seem to start the zwave network automatically when HA starts, I have to manually start it in /config/zwave
None of my ESPHome devices update temperature sensor readings -- The value change, but history does not reflect the change and statistics sensors don't work
Scripts with triggers with Home Assistant Start have not fired since upgrading to 0.113.1
There are no notifications for components that failed to start
There are no notifications for configuration errors

wolverinevn commented 4 years ago

Same issue. Have to roll-back 0.112. My error log:

xiaomi_miio air purifier (2S) cant finish setup
template cover does not have current_position (even thought support_features == 15)

neilenns commented 4 years ago

Same issue on my end as well, and same problem with zwave not auto-starting on boot.

dshokouhi commented 4 years ago

Can you guys turn on debug logging and look for something about waiting for a task to finish? You should see some logging about that.

neilenns commented 4 years ago

I've already rolled back to 0.112.4, this was breaking my entire home automation via NodeRed and unfortunately I can't have everything be down :(

deftdawg commented 4 years ago

@frenck This isn't specific to Zwave, it's a general startup problem.... zwave is just one of the many things that is not getting started

logbook shows no new entries since the upgrading to .113.1
backup snapshots cannot be taken
Home Assistant is being restarted after a number of hours

Me thinks, homeassistant.bootstrap needs some kind of timeout, and that timeout should be different from whatever the timeout supervisor uses (think supervisor uses 10min?) to make it easier to figure out which timeout is happening without digging through logs.

@danecreekphotography I feel your pain, none of the automatons I have work either

@dshokouhi my log is 48MB after three hours w/ the default log level, it already shows DEBUG messages, I don't think it's practical to do TRACE logging.

Did grep for wait and here's what came back:

2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency auth will wait for ['http']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency hassio will wait for ['http']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency onboarding will wait for ['auth', 'http', 'person']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency webhook will wait for ['http']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency websocket_api will wait for ['http']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency frontend will wait for ['api', 'auth', 'config', 'device_automation', 'http', 'lovelace', 'onboarding', 'search', 'system_log', 'websocket_api']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency config will wait for ['http']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency cloud will wait for ['http', 'webhook', 'alexa']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency search will wait for ['websocket_api']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency alexa will wait for ['http']
2020-07-27 10:28:09 DEBUG (MainThread) [homeassistant.setup] Dependency api will wait for ['http']
2020-07-27 10:28:10 DEBUG (MainThread) [homeassistant.setup] Dependency netatmo will wait for ['webhook']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency cast will wait for ['zeroconf']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency history will wait for ['http', 'recorder']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency wink will wait for ['configurator', 'http']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency mobile_app will wait for ['http', 'webhook', 'person', 'camera']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency mqtt will wait for ['http']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency discovery will wait for ['zeroconf']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency map will wait for ['frontend']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency zeroconf will wait for ['api']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency camera will wait for ['http', 'media_player']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency system_health will wait for ['http']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency media_player will wait for ['http']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency hacs will wait for ['websocket_api', 'frontend', 'persistent_notification', 'lovelace']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency conversation will wait for ['http']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency tts will wait for ['http', 'media_player']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency alert will wait for ['notify']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency default_config will wait for ['automation', 'cloud', 'frontend', 'history', 'logbook', 'map', 'mobile_app', 'person', 'scene', 'script', 'ssdp', 'sun', 'system_health', 'updater', 'zeroconf', 'zone', 'input_boolean', 'input_datetime', 'input_text', 'input_number', 'input_select']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency ssdp will wait for ['zeroconf']
2020-07-27 10:28:11 DEBUG (MainThread) [homeassistant.setup] Dependency logbook will wait for ['frontend', 'http', 'recorder']
2020-07-27 10:28:12 DEBUG (SyncWorker_2) [pyHS100.discover] Waiting 3 seconds for responses...
2020-07-27 10:28:18 DEBUG (MainThread) [homeassistant.setup] Dependency cast will wait for ['zeroconf']
2020-07-27 10:28:18 DEBUG (MainThread) [homeassistant.setup] Dependency device_tracker will wait for ['zone']
2020-07-27 10:28:18 DEBUG (MainThread) [homeassistant.setup] Dependency spotify will wait for ['http']
    await asyncio.wait_for(asyncio.shield(task), SLOW_SETUP_MAX_WAIT)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
2020-07-27 10:28:43 DEBUG (MainThread) [homeassistant.setup] Dependency stream will wait for ['http']
    await asyncio.wait_for(asyncio.shield(task), SLOW_SETUP_MAX_WAIT)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
2020-07-27 10:28:46 DEBUG (MainThread) [homeassistant.bootstrap] Waiting for startup to wrap up

dshokouhi commented 4 years ago

The debug log should show up around when HA starts up and seems it should be from homeassistant.core

Heres the PR that describes what to look for: https://github.com/home-assistant/core/pull/38134

I dont think it will catch all integrations but in order to fix the issue we need to find out which integration is causing start up from being blocked. Double check that all of your custom components are also disabled for the check, during the beta the team found one that blocked start up so thats a good thing to check too.

deftdawg commented 4 years ago

@dshokouhi, per your suggestion I changed my logging to this:

logger:
  default: info
  logs:
    homeassistant.core: debug

and much like @jurgenweber, when debug for .core is turned on startup was no longer blocked and home assistant started normally; everything works... 😕

I don't know if I should close this or not...

dshokouhi commented 4 years ago

@bdraco any thoughts on this?

bdraco commented 4 years ago

@bdraco any thoughts on this?

Debug being on won't affect startup. He just got lucky that whichever integration was blocking startup didn't happen to get stuck that time around. We have some integrations that don't have proper timeouts that reschedule a reconnect or update before the first one times out which means there is never a time window where startup can continue unblocked.

We probably need to adjust the logging to start showing which tasks are being waited for after we have blocked for 60 seconds. The original logging only shows if we are waiting for a single task for 60 seconds. It's a chain of tasks that never finish that is the issue in this case.

jurgenweber commented 4 years ago

@bdraco I agree with you in principle that the logging level wouldn't be doing this but I was switching it on and off, disabling integrations and it wouldn't start up completely. Automations/zwave were the two obvious parts that just never turned on (discussed lots on discord on Saturday). The only thing I realised in the end is I was switching the logging on and off all the time (i'd turn it on, think it was working... turn it off... then it wouldn't work again, drove me nuts :)).

But currently, I have it that core logging at warning and it worked....... argh.... I stopped at this point because my house was up again and that is all I wanted. :)

I let it sit for 40minutes once and nothing happened. The debug logging did not help. :(

So I am running the docker container, 0.113.1, I have two custom integrations (nsw fire and aarlo) and then I have the following integrations configured, I curled '/api/config' for this list

"binary_sensor.updater", "input_datetime", "input_text", "device_automation", "notify.group", "notify.mobile_app", "geo_location.nsw_rural_fire_service_feed", "media_player.sonos", "sensor.version", "onvif", "binary_sensor.workday", "sensor.unifi", "onboarding", "light.zwave", "sun", "camera.mqtt", "shell_command", "sensor.yr", "binary_sensor.tod", "light", "cloudflare", "media_player", "device_tracker.unifi", "stream", "updater", "notify.html5", "input_boolean", "persistent_notification", "switch.transmission", "sensor.daikin", "sensor.zwave", "websocket_api", "camera.aarlo", "climate.daikin", "input_number", "binary_sensor.cloud", "notify", "discovery", "alert", "aarlo", "binary_sensor", "switch", "camera.mjpeg", "rest_command", "sensor.onvif", "sensor.fastdotcom", "webhook", "binary_sensor.zwave", "zone", "speedtestdotnet", "switch.zwave", "lovelace", "alexa", "ffmpeg", "media_player.aarlo", "binary_sensor.onvif", "vacuum.roomba", "sensor.aarlo", "lock", "homeassistant", "transmission", "cast", "fastdotcom", "input_select", "binary_sensor.ping", "sonos", "sensor.speedtestdotnet", "group", "person", "media_player.cast", "unifi", "stt", "logger", "mobile_app", "auth", "zwave", "sensor.transmission", "sensor.local_ip", "device_tracker", "climate.zwave", "switch.aarlo", "weather.bom", "api", "sensor.season", "lock.zwave", "camera", "config", "sensor.mobile_app", "conversation", "sensor.mqtt", "binary_sensor.trend", "sensor.systemmonitor", "sensor.uptime", "http", "mqtt", "sensor.template", "timer", "camera.bom", "sensor.nsw_rural_fire_service_fire_danger", "vacuum", "binary_sensor.template", "camera.onvif", "sensor", "binary_sensor.aarlo", "tts", "cover.template", "frontend", "script", "cloud", "automation", "binary_sensor.mobile_app", "device_tracker.mobile_app", "system_log", "switch.unifi", "fan.zwave", "recorder", "weather", "light.switch", "search", "local_ip", "roomba", "cover.zwave", "cover", "daikin", "climate", "binary_sensor.roomba", "switch.daikin", "history", "system_health", "notify.file", "fan", "sensor.roomba", "sensor.transport_nsw", "light.aarlo", "geo_location", "counter", "sensor.darksky", "sensor.moon", "logbook"

I removed in my testing the custom integrations, cast, transmission, daikin and unifi mostly because these are the integrations I have had issues with before but I was able to restart it eventually with all of them working/setup.

That said, this is without a doubt the best HASS release I have experienced in my 3 years of using it. Everything is lighting fast, my zwave starts up in 5 minutes instead of 10. The automation fixes and changes are the best and I couldn't be happier.. Just a little afraid to restart atm. :) A big shout out to the team for all their efforts.

If you need me to do anything feel free to ping me on discord or here. Thanks

bdraco commented 4 years ago

Its probably onvif as I just fixed it https://github.com/home-assistant/core/pull/38256#pullrequestreview-455512124

neilenns commented 4 years ago

I have onvif integration in my config, so that's consistent with at least one other person who hit this.

jurgenweber commented 4 years ago

yeah, I did note my ONVIF was a bit weird, I have two devices and one of them the camera works but all of the sensors are unavailable.

wolverinevn commented 4 years ago

I don't use Onvif bit still get the issue. Have 5 Hass upgraded to 0.113 without issue, only one stuck with startup problem.

bdraco commented 4 years ago

Integrations reported to block startup:

[x] onvif in https://github.com/home-assistant/core/pull/38256#pullrequestreview-455512124 - fixed in 0.113.2
[x] ~~dyson here : https://github.com/home-assistant/core/issues/38273~~ (this one turned out to be a simple timeout, which eventually completes)
[x] kodi here : https://github.com/home-assistant/core/issues/38160 -- Fixed in 0.113.3 - https://github.com/home-assistant/core/pull/38257
[x] ~~tensorflow : One related here https://github.com/home-assistant/core/issues/38073 & https://github.com/home-assistant/core/issues/38081~~ -- was likely actually caused by onvif
[ ] minitemp_bt (beta version only) : and in https://github.com/home-assistant/core/issues/38088#issuecomment-663845111 was the issue. Reported here : https://github.com/custom-components/sensor.mitemp_bt/issues/98
[x] speedtestdotnet: https://www.reddit.com/r/homeassistant/comments/hwihb0/0113_upgrade_completed_successfully_ha_fails_to/fz82i6d?utm_source=share&utm_medium=web2x. Fixed in 0.113.2 - https://github.com/home-assistant/core/pull/38305
[x] doorbird: https://github.com/home-assistant/core/issues/38369 Pending fix in 0.114 https://github.com/home-assistant/core/pull/38619
[x] ping: https://github.com/home-assistant/core/issues/38468. Fixed in 0.114 / 0.113.4 https://github.com/home-assistant/core/pull/38504

Legend:

[ ] unfixed
[x] fixed

jurgenweber commented 4 years ago

is that all of them? Maybe then we close this ticket as a parent ticket for 'lots of integrations are stopping start up'.... in 0.113.0 and 0.113.1 and fixes are in 0.113.2....

bdraco commented 4 years ago

is that all of them?

I'm sure there are more. This isn't a new issue as these integrations have always had the risk of blocking startup because they can create a long running task that never finishes or a chain of these tasks that block forever. The chance of it happening increases as core gets faster since it more likely they will be doing the thing that blocks startup before bootstrap is completed.

Maybe then we close this ticket as a parent ticket for 'lots of integrations are stopping start up'.... in 0.113.0 and 0.113.1 and fixes are in 0.113.2....

Only onvif has been fixed.

jurgenweber commented 4 years ago

makes sense and thank you for the explaination.

jurgenweber commented 4 years ago

I can confirm the ONVIF issue, I deleted it and restarted.. it works.

neilenns commented 4 years ago

I'm terrified of rolling to any newer build of HomeAssistant if all it takes is one random integration taking too long/hanging to cause my entire home automation system to die...

bdraco commented 4 years ago

I'm terrified of rolling to any newer build of HomeAssistant if all it takes is one random integration taking too long/hanging to cause my entire home automation system to die...

Any integration can monopolize the event loop, run the system out of memory, or overwhelm the cpu. This is why we have code review to catch these type of things.

The good news is that as core gets faster, its more likely we find these type of problems and squash them for good instead of having them randomly pop up and go unsolved.

jurgenweber commented 4 years ago

I'm terrified of rolling to any newer build of HomeAssistant if all it takes is one random integration taking too long/hanging to cause my entire home automation system to die...

Any integration can monopolize the event loop, run the system out of memory, or overwhelm the cpu. This is why we have code review to catch these type of things.

and as already pointed out, these problems have always existed that just didn't become problems until the performance work was completed. So we will have this dark period of a bunch of integrations with issues and then it will become the norm and its over.

neilenns commented 4 years ago

This is why we have code review to catch these type of things.

https://github.com/home-assistant/core/issues/38274#issuecomment-664687168

🤔

deftdawg commented 4 years ago

I don't have any onvif stuff. A restart and back to broken...

Here's what I get loading by running

grep 'homeassistant.core' home-assistant.log | grep -v 'Event state_changed' | grep 'component_load'

2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logger>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=system_log>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=recorder>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=device_automation>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.auth_provider_homeassistant>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.device_registry>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.script>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.automation>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.area_registry>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.customize>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.entity_registry>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.scene>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.config_entries>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.core>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.group>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.auth>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=auth>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=webhook>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=alexa>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=api>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=websocket_api>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=lovelace>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config>
2020-07-27 21:07:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=search>
2020-07-27 21:07:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=person>
2020-07-27 21:07:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=cloud>
2020-07-27 21:07:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=onboarding>
2020-07-27 21:07:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=hassio>
2020-07-27 21:07:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=frontend>
2020-07-27 21:07:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=sun>
2020-07-27 21:07:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=shell_command>
2020-07-27 21:07:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=climate>
2020-07-27 21:07:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=configurator>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=weather>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=map>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=conversation>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=history>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=script>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=group>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=system_health>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=input_datetime>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=scene>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=input_text>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=updater>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=input_number>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=light>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=switch>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=input_select>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=input_boolean>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=binary_sensor>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=lametric>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=nuheat>
2020-07-27 21:07:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zwave>
2020-07-27 21:07:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=hangouts>
2020-07-27 21:07:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=netatmo>
2020-07-27 21:07:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logbook>
2020-07-27 21:07:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.zwave>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=media_player>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=esphome>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=fan>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=brother>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zeroconf>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=lock>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=mqtt>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=cover>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zone>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=notify>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=asuswrt>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=automation>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=ssdp>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=discovery>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=alert>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=tplink>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=cast>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=adguard>
2020-07-27 21:07:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=coronavirus>
2020-07-27 21:07:24 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=tesla>
2020-07-27 21:07:24 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=badnest>
2020-07-27 21:07:24 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=plum_lightpad>
2020-07-27 21:07:25 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zha>
2020-07-27 21:07:25 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=wink>
2020-07-27 21:07:25 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=device_tracker>
2020-07-27 21:07:25 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=harmony>
2020-07-27 21:07:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=hue>
2020-07-27 21:07:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=alarm_control_panel>
2020-07-27 21:07:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=water_heater>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=remote>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=camera>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=tts>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=sensor>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=nest>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=ffmpeg>
2020-07-27 21:07:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=upnp>
2020-07-27 21:07:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=wemo>
2020-07-27 21:07:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=mobile_app>
2020-07-27 21:07:42 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=stream>
2020-07-27 21:07:42 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=default_config>
2020-07-27 21:07:48 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=speedtestdotnet>
2020-07-27 21:07:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=hacs>

Also this zha_event continuously reoccurs in the log

2020-07-27 21:27:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:22:a3:00:00:0f:6b:b3, unique_id=00:22:a3:00:00:0f:6b:b3:1:0x0020, endpoint_id=1, cluster_id=32, command=checkin, args=[]>
2020-07-27 21:27:48 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:22:a3:00:00:0f:6b:b3, unique_id=00:22:a3:00:00:0f:6b:b3:1:0x0020, endpoint_id=1, cluster_id=32, command=checkin, args=[]>
2020-07-27 21:27:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:22:a3:00:00:0f:6b:b3, unique_id=00:22:a3:00:00:0f:6b:b3:1:0x0020, endpoint_id=1, cluster_id=32, command=checkin, args=[]>
2020-07-27 21:28:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:22:a3:00:00:0f:6b:b3, unique_id=00:22:a3:00:00:0f:6b:b3:1:0x0020, endpoint_id=1, cluster_id=32, command=checkin, args=[]>

@danecreekphotography @bdraco

This is why we have code review to catch these type of things.

#38274 (comment)

🤔

To be fair, a lot of the older components were built when the coding standards / objectives were a bit different.

jurgenweber commented 4 years ago

you have speedtesdotnet which @bdraco lists as a problem in https://github.com/home-assistant/core/issues/38274#issuecomment-664687168

deftdawg commented 4 years ago

Yup, I saw that removed and restarted, but I'm still seeing same problem... :(

bdraco commented 4 years ago

Yup, I saw that removed and restarted, but I'm still seeing same problem... :(

Did you try the logging suggested in this PR https://github.com/home-assistant/core/pull/38134. ?

Apologizes if you already have as I'm having trouble keeping track.

deftdawg commented 4 years ago

@bdraco I applied the debug logging, but didn't patch core.py... not sure if I can patch core within a docker container without rebuilding the whole thing...

On another note, my last Home Assistant run has finally gotten to startup in just over 2 hours...

2020-07-27 21:42:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=logger, service=set_default_level>
....
2020-07-28 00:23:47 INFO (MainThread) [homeassistant.core] Starting Home Assistant
2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event core_config_updated[L]>
2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zwave.network_start[L]>
2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event core_config_updated[L]>
2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_started[L]>
2020-07-28 00:23:47 INFO (MainThread) [homeassistant.core] Timer:starting

The only error I see relating to core is:

2020-07-28 00:24:09 ERROR (MainThread) [homeassistant.helpers.event] Error while processing state changed for sensor.basement_bathroom_esp_relative_humidity
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 168, in _async_state_change_dispatcher
    hass.async_run_job(action, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 112, in state_change_listener
    hass.async_run_job(
  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 229, in template_condition_listener
    template_result = condition.async_template(hass, template, variables)
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 400, in async_template
    value = value_template.async_render(variables)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 229, in async_render
    return compiled.render(kwargs).strip()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1090, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 832, in handle_exception
    reraise(*rewrite_traceback_stack(source=source))
  File "/usr/local/lib/python3.8/site-packages/jinja2/_compat.py", line 28, in reraise
    raise value.with_traceback(tb)
  File "<template>", line 2, in top-level template code
TypeError: can only concatenate str (not "float") to str
2020-07-28 00:24:09 ERROR (MainThread) [homeassistant.helpers.event] Error while processing state changed for sensor.basement_bathroom_esp_relative_humidity
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 168, in _async_state_change_dispatcher
    hass.async_run_job(action, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 112, in state_change_listener
    hass.async_run_job(
  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 229, in template_condition_listener
    template_result = condition.async_template(hass, template, variables)
  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 400, in async_template
    value = value_template.async_render(variables)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 229, in async_render
    return compiled.render(kwargs).strip()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1090, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 832, in handle_exception
    reraise(*rewrite_traceback_stack(source=source))
  File "/usr/local/lib/python3.8/site-packages/jinja2/_compat.py", line 28, in reraise
    raise value.with_traceback(tb)
  File "<template>", line 1, in top-level template code
TypeError: can only concatenate str (not "float") to str
2020-07-28 00:24:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.basement_bathroom_relative_humidity_for_past_2_hours, old_state=<state sensor.basement_bathroom_relative_humidity_for_past_2_hours=unknown; sampling_size=120, count=0, mean=unknown, median=unknown, standard_deviation=unknown, variance=unknown, total=unknown, min_value=unknown, max_value=unknown, min_age=2020-07-28T00:23:47.785320-04:00, max_age=2020-07-28T00:23:47.785320-04:00, change=unknown, average_change=unknown, change_rate=unknown, friendly_name=Basement Bathroom Relative Humidity for past 2 hours, icon=mdi:calculator @ 2020-07-27T21:42:31.698334-04:00>, new_state=<state sensor.basement_bathroom_relative_humidity_for_past_2_hours=52.8; sampling_size=120, count=1, mean=52.8, median=52.8, standard_deviation=unknown, variance=unknown, total=52.8, min_value=52.8, max_value=52.8, min_age=2020-07-28T00:24:09.614293-04:00, max_age=2020-07-28T00:24:09.614293-04:00, change=0.0, average_change=0.0, change_rate=0, unit_of_measurement=%, friendly_name=Basement Bathroom Relative Humidity for past 2 hours, icon=mdi:calculator @ 2020-07-28T00:24:09.626192-04:00>>

bdraco commented 4 years ago

@bdraco I applied the debug logging, but didn't patch core.py... not sure if I can patch core within a docker container without rebuilding the whole thing...

On another note, my last Home Assistant run has finally gotten to startup in just over 2 hours...


2020-07-27 21:42:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=logger, service=set_default_level>

....

2020-07-28 00:23:47 INFO (MainThread) [homeassistant.core] Starting Home Assistant

2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event core_config_updated[L]>

2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>

2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zwave.network_start[L]>

2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event core_config_updated[L]>

2020-07-28 00:23:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_started[L]>

2020-07-28 00:23:47 INFO (MainThread) [homeassistant.core] Timer:starting

The only error I see relating to core is:


2020-07-28 00:24:09 ERROR (MainThread) [homeassistant.helpers.event] Error while processing state changed for sensor.basement_bathroom_esp_relative_humidity

Traceback (most recent call last):

  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 168, in _async_state_change_dispatcher

    hass.async_run_job(action, event)

  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job

    target(*args)

  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 112, in state_change_listener

    hass.async_run_job(

  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job

    target(*args)

  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 229, in template_condition_listener

    template_result = condition.async_template(hass, template, variables)

  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 400, in async_template

    value = value_template.async_render(variables)

  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 229, in async_render

    return compiled.render(kwargs).strip()

  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1090, in render

    self.environment.handle_exception()

  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 832, in handle_exception

    reraise(*rewrite_traceback_stack(source=source))

  File "/usr/local/lib/python3.8/site-packages/jinja2/_compat.py", line 28, in reraise

    raise value.with_traceback(tb)

  File "<template>", line 2, in top-level template code

TypeError: can only concatenate str (not "float") to str

2020-07-28 00:24:09 ERROR (MainThread) [homeassistant.helpers.event] Error while processing state changed for sensor.basement_bathroom_esp_relative_humidity

Traceback (most recent call last):

  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 168, in _async_state_change_dispatcher

    hass.async_run_job(action, event)

  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job

    target(*args)

  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 112, in state_change_listener

    hass.async_run_job(

  File "/usr/src/homeassistant/homeassistant/core.py", line 381, in async_run_job

    target(*args)

  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 229, in template_condition_listener

    template_result = condition.async_template(hass, template, variables)

  File "/usr/src/homeassistant/homeassistant/helpers/condition.py", line 400, in async_template

    value = value_template.async_render(variables)

  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 229, in async_render

    return compiled.render(kwargs).strip()

  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1090, in render

    self.environment.handle_exception()

  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 832, in handle_exception

    reraise(*rewrite_traceback_stack(source=source))

  File "/usr/local/lib/python3.8/site-packages/jinja2/_compat.py", line 28, in reraise

    raise value.with_traceback(tb)

  File "<template>", line 1, in top-level template code

TypeError: can only concatenate str (not "float") to str

2020-07-28 00:24:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.basement_bathroom_relative_humidity_for_past_2_hours, old_state=<state sensor.basement_bathroom_relative_humidity_for_past_2_hours=unknown; sampling_size=120, count=0, mean=unknown, median=unknown, standard_deviation=unknown, variance=unknown, total=unknown, min_value=unknown, max_value=unknown, min_age=2020-07-28T00:23:47.785320-04:00, max_age=2020-07-28T00:23:47.785320-04:00, change=unknown, average_change=unknown, change_rate=unknown, friendly_name=Basement Bathroom Relative Humidity for past 2 hours, icon=mdi:calculator @ 2020-07-27T21:42:31.698334-04:00>, new_state=<state sensor.basement_bathroom_relative_humidity_for_past_2_hours=52.8; sampling_size=120, count=1, mean=52.8, median=52.8, standard_deviation=unknown, variance=unknown, total=52.8, min_value=52.8, max_value=52.8, min_age=2020-07-28T00:24:09.614293-04:00, max_age=2020-07-28T00:24:09.614293-04:00, change=0.0, average_change=0.0, change_rate=0, unit_of_measurement=%, friendly_name=Basement Bathroom Relative Humidity for past 2 hours, icon=mdi:calculator @ 2020-07-28T00:24:09.626192-04:00>>

You shouldn't have to patch core as since the logging changes are in 0.113.1 (not in .0)

deftdawg commented 4 years ago

Oh ok... I grepped the home-assistant.log for task, there were no lines that matched...

Went into the container and verified that the patch was there and it is...

grep -inr 'for task' ./src/homeassistant/homeassistant/core.py
 397:            pending = [task for task in self._pending_tasks if not task.done()] 
412:            for task in pending:      
413:                _LOGGER.debug("Waited %s seconds for task: %s", wait_time, task)

My log config is set to debug for homeassistant.core.... so not sure why that didn't work.

bdraco commented 4 years ago

Oh ok... I grepped the home-assistant.log for task, there were no lines that matched...

Went into the container and verified that the patch was there and it is...
grep -inr 'for task' ./src/homeassistant/homeassistant/core.py

 397:            pending = [task for task in self._pending_tasks if not task.done()] 

412:            for task in pending:      

413:                _LOGGER.debug("Waited %s seconds for task: %s", wait_time, task)
My log config is set to debug for homeassistant.core.... so not sure why that didn't work.

So it's likely the problem is a chain of tasks that never finish instead of a single one that takes more than 60 seconds. I'll work on a new PR to add additional logging for this case.

bdraco commented 4 years ago

https://github.com/home-assistant/core/pull/38311

New PR is here

deftdawg commented 4 years ago

I noticed looking through my logs that wink and qnap throw SLOW_SETUP_MAX_WAIT, so I'm going to remove them from my configuration as well.

2020-07-27 21:42:30 ERROR (MainThread) [homeassistant.components.light] Error while setting up wink platform for light
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 179, in _async_setup_platform
    await asyncio.wait_for(asyncio.shield(task), SLOW_SETUP_MAX_WAIT)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/wink/light.py", line 28, in setup_platform
    for light in pywink.get_light_groups():
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 636, in get_light_groups
    for group in get_devices(device_types.GROUP, "groups"):
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 710, in get_devices
    json_data = wink_api_fetch(end_point)
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 696, in wink_api_fetch
    raise WinkAPIException("Unexpected")
pywink.api.WinkAPIException: Unexpected
--
2020-07-27 21:42:30 ERROR (MainThread) [homeassistant.components.switch] Error while setting up wink platform for switch
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 179, in _async_setup_platform
    await asyncio.wait_for(asyncio.shield(task), SLOW_SETUP_MAX_WAIT)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/wink/switch.py", line 28, in setup_platform
    for switch in pywink.get_binary_switch_groups():
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 645, in get_binary_switch_groups
    for group in get_devices(device_types.GROUP, "groups"):
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 710, in get_devices
    json_data = wink_api_fetch(end_point)
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 696, in wink_api_fetch
    raise WinkAPIException("Unexpected")
pywink.api.WinkAPIException: Unexpected
--
2020-07-27 21:42:30 ERROR (MainThread) [homeassistant.components.cover] Error while setting up wink platform for cover
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 179, in _async_setup_platform
    await asyncio.wait_for(asyncio.shield(task), SLOW_SETUP_MAX_WAIT)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/wink/cover.py", line 16, in setup_platform
    for shade in pywink.get_shade_groups():
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 654, in get_shade_groups
    for group in get_devices(device_types.GROUP, "groups"):
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 710, in get_devices
    json_data = wink_api_fetch(end_point)
  File "/usr/local/lib/python3.8/site-packages/pywink/api.py", line 696, in wink_api_fetch
    raise WinkAPIException("Unexpected")
pywink.api.WinkAPIException: Unexpected
--
2020-07-27 21:42:39 ERROR (MainThread) [homeassistant.components.sensor] Error while setting up qnap platform for sensor
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 179, in _async_setup_platform
    await asyncio.wait_for(asyncio.shield(task), SLOW_SETUP_MAX_WAIT)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/qnap/sensor.py", line 152, in setup_platform
    for volume in config.get(CONF_VOLUMES, api.data["volumes"]):
KeyError: 'volumes'

dshokouhi commented 4 years ago

@deftdawg wink switched to their subscription model yesterday so that might be the cause of those errors

dennis84de commented 4 years ago

With the extended debugging in 0.113.2 I was able the figure out why HA wasn't starting up.

I found several messages regarding waiting for a task which pointed me to my fritzbox device tracker. After commenting that out, HA could start up without a problem.

2020-07-28 21:10:30 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished coro=<async_setup_scanner_platform.<locals>.async_device_tracker_scan() done, defined at /srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/device_tracker/setup.py:149> result=None>
2020-07-28 21:10:30 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=['...]>

Interestingly the fritzbox device tracker itself seemed to be working before as my devices had the correct state and were also updated correctly but HA ever could start up complete.

deftdawg commented 4 years ago

With 0.113.2, I'm seeing logging now but it's not obvious to me what the bottleneck to getting finished start up is...

2020-07-28 18:22:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8498' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8499' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8500' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8627' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8628' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8629' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8630' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8655' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8661' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8669' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8670' coro=<ConfigEntry.async_setup.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/config_entries.py:238> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8671' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:38 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:43 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8910' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:43 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8972' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8973' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8974' coro=<async_setup_scanner_platform.<locals>.async_device_tracker_scan() done, defined at /usr/src/homeassistant/homeassistant/components/device_tracker/setup.py:149> result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8975' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-8976' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9002' coro=<EntityPlatform._async_setup_platform.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:200> result=None>
2020-07-28 18:22:53 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9003' coro=<EntityPlatform._async_setup_platform.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:200> result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9097' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9102' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9103' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9104' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9105' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:03 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9128' coro=<ConfigEntry.async_setup.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/config_entries.py:238> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9131' coro=<ConfigEntry.async_setup.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/config_entries.py:238> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9326' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9479' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9480' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9481' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9482' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:13 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9524' coro=<Scanner.async_scan() done, defined at /usr/src/homeassistant/homeassistant/components/ssdp/__init__.py:55> result=None>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9599' coro=<EntityPlatform._async_setup_platform.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:200> result=None>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=[<UPNPEntry ht...MediaServer:1>, <UPNPEntry ht...np:rootdevice>, <UPNPEntry ht...-902704D8BD4C>, <UPNPEntry ht...ntDirectory:1>, <UPNPEntry ht...tionManager:1>, <UPNPEntry ht...np:rootdevice>, ...]>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9606' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9607' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9608' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 18:23:28 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-9609' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
...

jurgenweber commented 4 years ago

yeah, I hear you. Maybe wait longer?

I upgraded and it all works but my ONVIF was still un configured. I put it back in (after upgrade/restart), but yeah. So far so good.

deftdawg commented 4 years ago

@jurgenweber 5 hours and 328K tasks later... :rofl: :sob:

2020-07-28 23:24:24 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 23:24:24 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327958' coro=<Scanner.async_scan() done, defined at /usr/src/homeassistant/homeassistant/components/ssdp/__init__.py:55> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327974' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327975' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327976' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327977' coro=<EntityPlatform._update_entity_states() done, defined at /usr/src/homeassistant/homeassistant/helpers/entity_platform.py:534> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327978' coro=<ConfigEntry.async_setup.<locals>.setup_again() done, defined at /usr/src/homeassistant/homeassistant/config_entries.py:238> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Task finished name='Task-327979' coro=<async_setup_scanner_platform.<locals>.async_device_tracker_scan() done, defined at /usr/src/homeassistant/homeassistant/components/device_tracker/setup.py:149> result=None>
2020-07-28 23:24:34 DEBUG (MainThread) [homeassistant.core] Waiting for task: <Future finished result=[<UPNPEntry ht...np:rootdevice>, <UPNPEntry ht...tionManager:1>, <UPNPEntry ht...-902704D8BD4C>, <UPNPEntry ht...MediaServer:1>, <UPNPEntry ht...ntDirectory:1>, <UPNPEntry ht...np:rootdevice>, ...]>

jurgenweber commented 4 years ago

remove device_tracker stuff and upnp? ALl I got.. :0

linsvensson commented 4 years ago

I had the same problem. But it started working again when I removed - platform: bluetooth_tracker Have you tried that?

sivero commented 4 years ago

Fresh install with VMware VM, same problem here. Tried skipping all integrations and ignoring discovered ones too

kitsune0n commented 4 years ago

have the same problem after update to 0.113.2

bdraco commented 4 years ago

@sivero @foxacc

Please follow the instructions in this PR https://github.com/home-assistant/core/pull/38134 and post the results

sivero commented 4 years ago

After trying many things I found out the problem: I have a netatmo welcome camera, the integrations page was detecting it and I had no configuration made for it yet. When I turned the camera off (unplugged it) and restart home assistant it worked. But if I started home assistant with the camera on, it didn’t work. The way I fixed the problem is by adding the netatmo configuration in a yaml and restarted. After that, no more problem... at least for now.

bdraco commented 4 years ago

After trying many things I found out the problem: I have a netatmo welcome camera, the integrations page was detecting it and I had no configuration made for it yet. When I turned the camera off (unplugged it) and restart home assistant it worked. But if I started home assistant with the camera on, it didn’t work. The way I fixed the problem is by adding the netatmo configuration in a yaml and restarted. After that, no more problem... at least for now.

@sivero Thanks for reporting this.

@cgtobi is working hard to improve the netatmo integration here https://github.com/home-assistant/core/pull/35571

wernerhp commented 4 years ago

0.113.2 I had this too

Restarting from Configuration > Server Controls didn't seem to do much. I had to restart the homeassistant docker container manually. No longer getting this. Here are some errors that came up before.

2020-08-01 13:36:24 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: media_extractor, notify, camera, withings, xiaomi_aqara, hacs

2020-08-01 15:54:42 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.pressure_lumi_xxxxx fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 192, in send
    data, addr = s.recvfrom(1024)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 918, in get_property_exp
    response = self._gw.send(
  File "/usr/local/lib/python3.8/site-packages/miio/device.py", line 146, in send
    return self._protocol.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 232, in send
    return self.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 160, in send
    self.send_handshake()
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 87, in send_handshake
    raise DeviceException("Unable to discover the device %s" % self.ip)
miio.exceptions.DeviceException: Unable to discover the device 192.168.1.230

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/xiaomi_miio/gateway.py", line 100, in async_update
    await self.hass.async_add_executor_job(self._sub_device.update)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 1209, in update
    values = self.get_property_exp(self.properties)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 923, in get_property_exp
    "Got an exception while fetching properties %s: %s" % (properties)
TypeError: not enough arguments for format string
2020-08-01 15:54:42 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.temperature_lumi_xxxxx fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 192, in send
    data, addr = s.recvfrom(1024)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 918, in get_property_exp
    response = self._gw.send(
  File "/usr/local/lib/python3.8/site-packages/miio/device.py", line 146, in send
    return self._protocol.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 232, in send
    return self.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 160, in send
    self.send_handshake()
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 87, in send_handshake
    raise DeviceException("Unable to discover the device %s" % self.ip)
miio.exceptions.DeviceException: Unable to discover the device 192.168.1.230

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/xiaomi_miio/gateway.py", line 100, in async_update
    await self.hass.async_add_executor_job(self._sub_device.update)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 1209, in update
    values = self.get_property_exp(self.properties)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 923, in get_property_exp
    "Got an exception while fetching properties %s: %s" % (properties)
TypeError: not enough arguments for format string
2020-08-01 15:54:42 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.humidity_lumi_xxxxx fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 192, in send
    data, addr = s.recvfrom(1024)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 918, in get_property_exp
    response = self._gw.send(
  File "/usr/local/lib/python3.8/site-packages/miio/device.py", line 146, in send
    return self._protocol.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 232, in send
    return self.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 160, in send
    self.send_handshake()
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 87, in send_handshake
    raise DeviceException("Unable to discover the device %s" % self.ip)
miio.exceptions.DeviceException: Unable to discover the device 192.168.1.230

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/xiaomi_miio/gateway.py", line 100, in async_update
    await self.hass.async_add_executor_job(self._sub_device.update)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 1209, in update
    values = self.get_property_exp(self.properties)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 923, in get_property_exp
    "Got an exception while fetching properties %s: %s" % (properties)
TypeError: not enough arguments for format string
2020-08-01 15:54:42 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.pressure_lumi_xxxxx fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 192, in send
    data, addr = s.recvfrom(1024)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 918, in get_property_exp
    response = self._gw.send(
  File "/usr/local/lib/python3.8/site-packages/miio/device.py", line 146, in send
    return self._protocol.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 232, in send
    return self.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 160, in send
    self.send_handshake()
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 87, in send_handshake
    raise DeviceException("Unable to discover the device %s" % self.ip)
miio.exceptions.DeviceException: Unable to discover the device 192.168.1.230

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/xiaomi_miio/gateway.py", line 100, in async_update
    await self.hass.async_add_executor_job(self._sub_device.update)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 1209, in update
    values = self.get_property_exp(self.properties)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 923, in get_property_exp
    "Got an exception while fetching properties %s: %s" % (properties)
TypeError: not enough arguments for format string
2020-08-01 15:54:42 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.temperature_lumi_xxxxx fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 192, in send
    data, addr = s.recvfrom(1024)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 918, in get_property_exp
    response = self._gw.send(
  File "/usr/local/lib/python3.8/site-packages/miio/device.py", line 146, in send
    return self._protocol.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 232, in send
    return self.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 160, in send
    self.send_handshake()
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 87, in send_handshake
    raise DeviceException("Unable to discover the device %s" % self.ip)
miio.exceptions.DeviceException: Unable to discover the device 192.168.1.230

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/xiaomi_miio/gateway.py", line 100, in async_update
    await self.hass.async_add_executor_job(self._sub_device.update)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 1209, in update
    values = self.get_property_exp(self.properties)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 923, in get_property_exp
    "Got an exception while fetching properties %s: %s" % (properties)
TypeError: not enough arguments for format string
2020-08-01 15:54:42 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.humidity_lumi_xxxxx fails
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 918, in get_property_exp
    response = self._gw.send(
  File "/usr/local/lib/python3.8/site-packages/miio/device.py", line 146, in send
    return self._protocol.send(
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 160, in send
    self.send_handshake()
  File "/usr/local/lib/python3.8/site-packages/miio/miioprotocol.py", line 87, in send_handshake
    raise DeviceException("Unable to discover the device %s" % self.ip)
miio.exceptions.DeviceException: Unable to discover the device 192.168.1.230

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/xiaomi_miio/gateway.py", line 100, in async_update
    await self.hass.async_add_executor_job(self._sub_device.update)
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 1209, in update
    values = self.get_property_exp(self.properties)
  File "/usr/local/lib/python3.8/site-packages/miio/gateway.py", line 923, in get_property_exp
    "Got an exception while fetching properties %s: %s" % (properties)
TypeError: not enough arguments for format string

bdraco commented 4 years ago

@wernerhp Please turn on debug logging for homeassistant.core, and please post the log if it happens again.

gio-dot commented 4 years ago

Similar issue for me: https://github.com/home-assistant/core/issues/38453 I will check log later.

gio-dot commented 4 years ago

Similar issue for me: #38453 I will check log later.

Solved for me: was this custom component not updated: https://github.com/custom-components/sensor.mitemp_bt Thank you all

bdraco commented 4 years ago

I'm terrified of rolling to any newer build of HomeAssistant if all it takes is one random integration taking too long/hanging to cause my entire home automation system to die...

@danecreekphotography You shouldn't have to worry about this anymore as of 0.114:

An intelligent timeout handler has been added to 0.114 in #38329 that should prevent most integrations from blocking startup.

Additionally the other known cases should be fixed by #38601 which should close out this issue for good.

home-assistant / core

0.113.2 - Home Assistant is starting, not everything will be available until it is finished. #38274

The problem

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

Additional information

Problem-relevant `configuration.yaml`