search

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
73.31k stars 30.62k forks source link

Automation integration not waiting for requirements to be installed #33104

Closed jason0x43 closed 4 years ago

jason0x43 commented 4 years ago

The problem

I wrote a hubitat integration. Sometimes after updating Home Assistant, I'll get a notification in the HA UI that there was a problem with the automation integration (jason0x43/hacs-hubitat#29). From my logs, it looks like:

  1. HA starts installing hubitat's required package, hubitatmaker
  2. The device_automation integration tries to load hubitat and fails
  3. The device_automation integration finishes loading
  4. The hubitat integration loads (presumably after the dependency finished installing)

If I restart HA again, everything works fine.

It's entirely possible I missed something in the init code for my integration. However, it looks like there may also be a problem in the device_automation integration: it uses loader.async_get_integration rather than requirements.async_get_integration_with_requirements, so it won't wait for required packages to be loaded for custom integrations.

Environment

Problem-relevant configuration.yaml

Both the hubitat integration and device_automation are configured via the UI.

Traceback/Error logs

This is a startup log from just after I installed HA 0.107.2. HA starts installing the hubitatmaker dependency at line 36, has problems loading the hubitat integration for device_automation at line 57, and eventually loads the hubitat integration at line 170.

  1 2020-03-20 15:50:35 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for dyson which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
  2 2020-03-20 15:50:35 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
  3 2020-03-20 15:50:35 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hubitat which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
  4 2020-03-20 15:50:35 INFO (MainThread) [homeassistant.setup] Setup of domain logger took 0.0 seconds.
  5 2020-03-20 15:50:35 INFO (MainThread) [homeassistant.setup] Setting up http
  6 2020-03-20 15:50:35 INFO (MainThread) [homeassistant.setup] Setup of domain http took 0.0 seconds.
  7 2020-03-20 15:50:35 INFO (MainThread) [homeassistant.setup] Setting up system_log
  8 2020-03-20 15:50:35 INFO (MainThread) [homeassistant.setup] Setup of domain system_log took 0.0 seconds.
  9 2020-03-20 15:50:36 INFO (MainThread) [homeassistant.setup] Setting up recorder
 10 2020-03-20 15:50:36 INFO (MainThread) [homeassistant.setup] Setting up webhook
 11 2020-03-20 15:50:36 INFO (MainThread) [homeassistant.setup] Setup of domain webhook took 0.0 seconds.
 12 2020-03-20 15:50:36 INFO (MainThread) [homeassistant.setup] Setting up alexa
 13 2020-03-20 15:50:36 INFO (MainThread) [homeassistant.setup] Setup of domain alexa took 0.0 seconds.
 14 2020-03-20 15:50:36 INFO (MainThread) [homeassistant.setup] Setup of domain recorder took 0.9 seconds.
 15 2020-03-20 15:50:36 INFO (SyncWorker_1) [homeassistant.loader] Loaded google_assistant from homeassistant.components.google_assistant
 16 2020-03-20 15:50:37 INFO (SyncWorker_3) [homeassistant.loader] Loaded device_tracker from homeassistant.components.device_tracker
 17 2020-03-20 15:50:39 INFO (MainThread) [homeassistant.setup] Setting up cloud
 18 2020-03-20 15:50:39 INFO (MainThread) [homeassistant.setup] Setup of domain cloud took 0.1 seconds.
 19 2020-03-20 15:50:39 INFO (MainThread) [homeassistant.setup] Setting up dyson
 20 2020-03-20 15:50:39 INFO (SyncWorker_4) [custom_components.dyson] Creating new Dyson component
 21 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up ffmpeg
 22 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up scene
 23 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up zone
 24 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up input_text
 25 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up input_datetime
 26 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up input_number
 27 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up updater
 28 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up lovelace
 29 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up script
 30 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain script took 0.0 seconds.
 31 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up life360
 32 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up ssdp
 33 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain ssdp took 0.0 seconds.
 34 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up group
 35 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain group took 0.0 seconds.
 36 2020-03-20 15:50:40 INFO (SyncWorker_6) [homeassistant.util.package] Attempting install of hubitatmaker>=0.3.2,<0.4.0
 37 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up input_select
 38 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up input_boolean
 39 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up sun
 40 2020-03-20 15:50:40 INFO (SyncWorker_2) [homeassistant.loader] Loaded darksky from homeassistant.components.darksky
 41 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain sun took 0.0 seconds.
 42 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 43 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 44 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 45 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 46 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 47 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 48 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 49 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 50 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up person
 51 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain life360 took 0.3 seconds.
 52 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up api
 53 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up system_health
 54 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain system_health took 0.0 seconds.
 55 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up history
 56 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain history took 0.0 seconds.
 57 2020-03-20 15:50:40 ERROR (MainThread) [homeassistant.config] Invalid config for [automation]: Integration 'hubitat' does not support device automation triggers (See /config/configuration.yaml, line 10).
 58 2020-03-20 15:50:40 ERROR (MainThread) [homeassistant.config] Invalid config for [automation]: Integration 'hubitat' does not support device automation triggers (See /config/configuration.yaml, line 10).
 59 2020-03-20 15:50:40 ERROR (MainThread) [homeassistant.config] Invalid config for [automation]: Integration 'hubitat' does not support device automation triggers (See /config/configuration.yaml, line 10).
 60 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up config
 61 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up device_automation
 62 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain device_automation took 0.0 seconds.
 63 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up websocket_api
 64 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain websocket_api took 0.0 seconds.
 65 2020-03-20 15:50:40 INFO (SyncWorker_5) [homeassistant.loader] Loaded light from homeassistant.components.light
 66 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain input_text took 0.7 seconds.
 67 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain input_datetime took 0.7 seconds.
 68 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain input_number took 0.7 seconds.
 69 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up auth
 70 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain auth took 0.0 seconds.
 71 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain input_boolean took 0.4 seconds.
 72 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain input_select took 0.4 seconds.
 73 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain api took 0.3 seconds.
 74 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain lovelace took 0.7 seconds.
 75 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain config took 0.1 seconds.
 76 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up search
 77 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain search took 0.0 seconds.
 78 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up automation
 79 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.scene] Setting up scene.homeassistant
 80 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain scene took 0.8 seconds.
 81 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain zone took 0.8 seconds.
 82 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up device_tracker
 83 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain automation took 0.0 seconds.
 84 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain person took 0.4 seconds.
 85 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setting up onboarding
 86 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain onboarding took 0.0 seconds.
 87 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.setup] Setup of domain device_tracker took 0.1 seconds.
 88 2020-03-20 15:50:40 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.legacy
 89 2020-03-20 15:50:41 INFO (SyncWorker_4) [custom_components.dyson] Connected to Dyson account
 90 2020-03-20 15:50:41 INFO (MainThread) [homeassistant.components.updater] Submitted analytics to Home Assistant servers. Information submitted includes {}
 91 2020-03-20 15:50:41 INFO (MainThread) [homeassistant.setup] Setup of domain updater took 1.3 seconds.
 92 2020-03-20 15:50:42 INFO (SyncWorker_4) [custom_components.dyson] Trying to connect to device DysonPureHotCool(...)
 93 2020-03-20 15:50:42 INFO (MainThread) [homeassistant.setup] Setup of domain ffmpeg took 2.9 seconds.
 94 2020-03-20 15:50:43 INFO (SyncWorker_4) [custom_components.dyson] Connected to device DysonPureHotCool(...)
 95 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setup of domain dyson took 3.6 seconds.
 96 2020-03-20 15:50:43 INFO (SyncWorker_2) [homeassistant.loader] Loaded fan from homeassistant.components.fan
 97 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setting up fan
 98 2020-03-20 15:50:43 INFO (SyncWorker_0) [homeassistant.loader] Loaded vacuum from homeassistant.components.vacuum
 99 2020-03-20 15:50:43 INFO (SyncWorker_2) [homeassistant.loader] Loaded climate from homeassistant.components.climate
100 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setup of domain fan took 0.0 seconds.
101 2020-03-20 15:50:43 INFO (SyncWorker_3) [homeassistant.loader] Loaded air_quality from homeassistant.components.air_quality
102 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setting up vacuum
103 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setup of domain vacuum took 0.0 seconds.
104 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setting up climate
105 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setup of domain climate took 0.0 seconds.
106 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setting up air_quality
107 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.setup] Setup of domain air_quality took 0.0 seconds.
108 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.components.fan] Setting up fan.dyson
109 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.components.vacuum] Setting up vacuum.dyson
110 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.components.climate] Setting up climate.dyson
111 2020-03-20 15:50:43 INFO (MainThread) [homeassistant.components.air_quality] Setting up air_quality.dyson
112 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up homekit
113 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up sonos
114 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds.
115 2020-03-20 15:51:02 INFO (SyncWorker_4) [homeassistant.loader] Loaded template from homeassistant.components.template
116 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up weather
117 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up alarm_control_panel
118 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up binary_sensor
119 2020-03-20 15:51:02 INFO (SyncWorker_8) [homeassistant.loader] Loaded uptime from homeassistant.components.uptime
120 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setup of domain alarm_control_panel took 0.1 seconds.
121 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.template
122 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up media_player
123 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setting up sensor
124 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.uptime
125 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.template
126 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.1 seconds.
127 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
128 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setup of domain homekit took 0.7 seconds.
129 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setup of domain binary_sensor took 0.2 seconds.
130 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 0.1 seconds.
131 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.updater
132 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.dyson
133 2020-03-20 15:51:02 INFO (MainThread) [homeassistant.components.weather] Setting up weather.darksky
134 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setting up stream
135 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setup of domain stream took 0.4 seconds.
136 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setting up konnected
137 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setup of domain konnected took 0.0 seconds.
138 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Set up binary_sensor Balcony Door (initial state: None)
139 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Set up binary_sensor Front Door (initial state: None)
140 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Set up binary_sensor Garage Back Door (initial state: None)
141 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Set up binary_sensor Garage Side Door (initial state: None)
142 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Set up binary_sensor East Sliding Door (initial state: None)
143 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Set up binary_sensor West Sliding Door (initial state: None)
144 2020-03-20 15:51:03 DEBUG (MainThread) [homeassistant.components.konnected.panel] Storing data in hass.data[konnected][devices][...]: {...}
145 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setting up hue
146 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setup of domain hue took 0.0 seconds.
147 2020-03-20 15:51:03 INFO (MainThread) [homeassistant.setup] Setting up zeroconf
148 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setting up frontend
149 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setup of domain frontend took 0.0 seconds.
150 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setup of domain zeroconf took 0.5 seconds.
151 2020-03-20 15:51:04 INFO (SyncWorker_0) [homeassistant.loader] Loaded homekit_controller from homeassistant.components.homekit_controller
152 2020-03-20 15:51:04 INFO (SyncWorker_6) [homeassistant.loader] Loaded spotify from homeassistant.components.spotify
153 2020-03-20 15:51:04 INFO (SyncWorker_2) [homeassistant.loader] Loaded brother from homeassistant.components.brother
154 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setup of domain weather took 1.8 seconds.
155 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setting up map
156 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setup of domain map took 0.0 seconds.
157 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setting up logbook
158 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setup of domain logbook took 0.0 seconds.
159 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.hue
160 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.hue
161 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.components.konnected.panel] Connected to new Konnected device
162 2020-03-20 15:51:04 DEBUG (MainThread) [homeassistant.components.konnected.panel] {...}
163 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setting up light
164 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.setup] Setup of domain light took 0.1 seconds.
165 2020-03-20 15:51:04 DEBUG (MainThread) [homeassistant.components.konnected.config_flow] {...}
166 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.components.light] Setting up light.hue
167 2020-03-20 15:51:04 DEBUG (MainThread) [homeassistant.components.konnected.panel] Device ... settings payload: {...}
168 2020-03-20 15:51:04 INFO (MainThread) [homeassistant.components.konnected.panel] pushing settings to device ...
169 2020-03-20 15:51:04 DEBUG (MainThread) [homeassistant.components.konnected.config_flow] {...}
170 2020-03-20 15:51:05 INFO (MainThread) [homeassistant.setup] Setting up hubitat
171 2020-03-20 15:51:05 INFO (MainThread) [homeassistant.setup] Setup of domain hubitat took 0.0 seconds.
172 2020-03-20 15:51:05 INFO (MainThread) [hubitatmaker.hub] Created hub <Hub host=10.0.1.99 app_id=2269>
173 2020-03-20 15:51:05 INFO (MainThread) [hubitatmaker.hub] Setting event update URL to http://10.0.1.248:45733

Additional information

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

Hey there @home-assistant/core, mind taking a look at this issue as its been labeled with a integration (device_automation) you are listed as a codeowner for? Thanks!

balloob commented 4 years ago

Yeah what is happening here is that we assume that we can load any integration because the user has configured a device automation for it. However, when you upgrade, the image is new and it might still need to install dependencies for custom integrations.

We should use your proposed function, do you want to open a PR? We should also include caching in async_get_integration_with_requirements to make sure that we don't check integrations twice.

jason0x43 commented 4 years ago

Sure, I'll work on a PR.