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

Created on 27 Jul 2020 · 50Comments · Source: home-assistant/core

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

zwave

Source

deftdawg

👍2

Most helpful comment

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.

bdraco on 28 Jul 2020

👍4

All 50 comments

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)

wolverinevn on 27 Jul 2020

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

danecreekphotography on 27 Jul 2020

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.

dshokouhi on 27 Jul 2020

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 :(

danecreekphotography on 27 Jul 2020

@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

deftdawg on 27 Jul 2020

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.

dshokouhi on 27 Jul 2020

@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...

deftdawg on 27 Jul 2020

👍1

@bdraco any thoughts on this?

dshokouhi on 27 Jul 2020

@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.

bdraco on 27 Jul 2020

@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

jurgenweber on 28 Jul 2020

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

bdraco on 28 Jul 2020

🎉1

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

danecreekphotography on 28 Jul 2020

👍1

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.

jurgenweber on 28 Jul 2020

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.

wolverinevn on 28 Jul 2020

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

bdraco on 28 Jul 2020

👍2 😄1

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....

jurgenweber on 28 Jul 2020

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.

bdraco on 28 Jul 2020

😄1

makes sense and thank you for the explaination.

jurgenweber on 28 Jul 2020

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

jurgenweber on 28 Jul 2020

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 on 28 Jul 2020

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.

bdraco on 28 Jul 2020

👍4

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.

jurgenweber on 28 Jul 2020

🚀1 😄1

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

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

🤔

danecreekphotography on 28 Jul 2020

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.

deftdawg on 28 Jul 2020

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

jurgenweber on 28 Jul 2020

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

deftdawg on 28 Jul 2020

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.

bdraco on 28 Jul 2020

@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>>

deftdawg on 28 Jul 2020

@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)

bdraco on 28 Jul 2020

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.

deftdawg on 28 Jul 2020

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 on 28 Jul 2020

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

New PR is here

bdraco on 28 Jul 2020

👍1

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'

deftdawg on 28 Jul 2020

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

dshokouhi on 28 Jul 2020

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.

dennis84de on 28 Jul 2020

👍1

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> ...

deftdawg on 29 Jul 2020

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.

jurgenweber on 29 Jul 2020

@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>, ...]>

deftdawg on 29 Jul 2020

😕1

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

jurgenweber on 29 Jul 2020

👀1

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

linsvensson on 29 Jul 2020

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

sivero on 30 Jul 2020

👍1

have the same problem after update to 0.113.2

foxacc on 31 Jul 2020

@sivero @foxacc

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

bdraco on 31 Jul 2020

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 on 31 Jul 2020

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

bdraco on 31 Jul 2020

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

wernerhp on 1 Aug 2020

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

bdraco on 1 Aug 2020

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

Gio-dot on 1 Aug 2020

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

Gio-dot on 2 Aug 2020

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.

bdraco on 7 Aug 2020

❤1

Was this page helpful?

0 / 5 - 0 ratings

Related issues

tellduslive fails after upgrade to 0.80.1

Konstigt · 3Comments

Rewrite facebook unittest tests to pytest style test functions

MartinHjelmare · 3Comments

Hassio component missing after upgrade to 0.90.0b4

TheZoker · 3Comments

Samsung SyncThru Printer gets rediscovered on every restart resulting in multiple integration entries

YellowMonster76 · 3Comments

Impossible to send Authorization headers

piitaya · 3Comments

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

The problem

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

Additional information

Most helpful comment

All 50 comments

Related issues

Problem-relevant `configuration.yaml`