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
72.74k stars 30.46k forks source link

Dependency for mqtt component does not work as expected #92297

Closed jbouwh closed 1 year ago

jbouwh commented 1 year ago

The problem

Change https://github.com/home-assistant/core/pull/92296 was needed to make sure the snips integration set's up. It failed because mqtt was not available, while that should not be possible. It is known that if an integration is set up as a platform it could be triggered by the mqtt platform setup. But snips is an integration component that should wait for the mqtt integration component as a dependency. Issue https://github.com/home-assistant/core/issues/92236 proves this does not work.

What version of Home Assistant Core has the issue?

core-dev-2023.5.b0

What was the last working version of Home Assistant Core?

core-dev-2023.4.0

What type of installation are you running?

Home Assistant OS

Integration causing the issue

mqtt

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 1 year ago

snips documentation snips source

home-assistant[bot] commented 1 year ago

Hey there @emontnemery, mind taking a look at this issue as it has been labeled with an integration (mqtt) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `mqtt` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign mqtt` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


mqtt documentation mqtt source (message by IssueLinks)

diplix commented 1 year ago

@jbouwh asked in https://github.com/home-assistant/core/issues/92236#issuecomment-1529058634

May be you have some other stuff that takes some time to startup

i do, actually. first came the fritz integration to my mind, which takes about 140 seconds. when i looked again, there’s the xiaomi_miio_fan integration that takes a staggerin 862 seconds — although it was deactivated in the frontend. also, since i use a lot of command line sensors, the command line integration takes 23 seconds.

as far as i understand, none of the above mentioned intergrations use mqtt and after startup, mqtt usally is up shortly after the fritz integration is up. i never see any mention of the xiaomi_miio_fan integration in the startup notificaton („HA has not initialized completly, starting xxx“).

image Bildschirmfoto 2023-04-30 um 20 13 17
jbouwh commented 1 year ago

Okay, any other integrations in configuration.yaml like snips? HA should hold snips until mqtt is set up. MQTT also sets up platforms that will trigger integration with a platform setup. If that takes too long we could have a time out. Given the startup time of HA in your case there is a good possibility this happens. MQTT it self did not take much time, but when snips errors the mqtt platform setup was not started yet. The setup time of stage 2 (that is where mqtt and snips get set up) time out at 300 seconds. Can you check you have this in out log after startup?: Setup timed out for stage 2 - moving forward

jbouwh commented 1 year ago

It seems your xiaomi_miio_fan takes a long time to set up. Could you test what happens during setup if you temporary disable this integration?

diplix commented 1 year ago

deactivating xiaomi_miio_fan in my configuration (instead of only deactivating it in the frontend) does not help, snips won’t start without the snips-integration check for MQTT availability. i also observed that the error („[snips] could not be set up“) is occuring before the fritz integration is even shown to be inializing.

so, as you said, it’s probably some other plattforms that MQTT tries to set up, that might take time.

i have one more integration that directly utilizes mqtt: owntracks no problems initializing here, reported startup time for owntracks is a mere 0.31 seconds. i’m also using a couple of mqtt device_trackers. another source of interference might be, that i use a lot of mqtt device triggers like this:

  trigger:
  - platform: device
    domain: mqtt
    device_id: e9749d3349084a139c8afae226123774
    type: action
    subtype: single_right
    discovery_id: 0x00158d000238a914 action_single_right

and also lots of mqtt subscriptions as triggers

  - platform: mqtt
    topic: zigbee2mqtt/tradfri_schalter_6

however HA reports 0.14 seconds startup time for automation zigbee2mqtt autodiscovery probably puts most stress to the mqtt initialisation.

jbouwh commented 1 year ago

deactivating xiaomi_miio_fan in my configuration (instead of only deactivating it in the frontend) does not help, snips won’t start without the snips-integration check for MQTT availability. i also observed that the error („[snips] could not be set up“) is occuring before the fritz integration is even shown to be inializing.

so, as you said, it’s probably some other plattforms that MQTT tries to set up, that might take time.

It is that xiaomi_miio takes more than 300, after that the dependencies might not work any more. To test disabling the xiaomi_miio integration you should disable all entries. The device triggers will startup normally as they are platform setup's.

diplix commented 1 year ago

yes, that’s what i did, disable all entries of the xiaomi_miio integration, but it had no impact as snips still won’t start without the check, as i wrote above.

home-assistant[bot] commented 1 year ago

Hey there @rytilahti, @syssi, @starkillerog, mind taking a look at this issue as it has been labeled with an integration (xiaomi_miio) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `xiaomi_miio` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign xiaomi_miio` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


xiaomi_miio documentation xiaomi_miio source (message by IssueLinks)

jbouwh commented 1 year ago

If have linked xiaomi_miio as integration. I cannot explain why you are seeing in the startup time where you did not have enabled entries.

jbouwh commented 1 year ago

Interesting is that mqtt will wait for the platforms to be set up before it is finished. In you case mqtt did not take a long time. What I would like to know is the moment where mqtt and snips were started. May be snips was waiting a long time. I do not see snips in your startup time list. Perhaps you can share some relevant details of your startup log files.

jbouwh commented 1 year ago

If you disable all xiaomi_miio entries, it should not be listed in the list with the integration startup times.

diplix commented 1 year ago

If have linked xiaomi_miio as integration. I cannot explain why you are seeing in the startup time where you did not have enabled entries.

thats not what i said. when i reported the issue xiaomi_miio_fan had a configured entity in yaml which was disabled in the frontend. this resulted in the 851 second startup time. (this might be another issue, that a configuration entry in yaml that is disabled in the frontend results in a 800+ seconds startup time of the integration, but lets not get into that here)

after you asked to disable the configured entries i did so (in yaml). after that i could (of course) not see any startup time for the integration anymore. but it also did not help in terms of initialising the snips integration — i still need the mqtt-check to be present.

diplix commented 1 year ago

I do not see snips in your startup time list. Perhaps you can share some relevant details of your startup log files.

snips takes 1.66 seconds to start up. i’ll have a look in the log files and see what i can find after i set he logs to more verbose reporting (as per default setting integration startup is not logged).

jbouwh commented 1 year ago

Do you have any custom integrations set up?

diplix commented 1 year ago

i do have some custom integrations, as you see below. i’ll try to reproduce the issue on a fresh, local HA install, to which, untill now, i had no success. however i saw one thing in the startup/setup logs that made me wonder:

2023-05-02 10:12:18.514 DEBUG (MainThread) [homeassistant.setup] Dependency mysensors will wait for after dependencies ['mqtt']

i have mysensor set up as a serial connection, not as mqtt, which is theoretically also possible. with a serial connection, mysensors should actually not have to wait for mqtt? (mysensors takes 5 seconds to set up)


here are some logs. i do not know whether the order in the logs is the actual order for setting up the stages. if so, there are quite some integration setups between mqtt and snips.

2023-05-02 10:12:17.247 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 1: {'ssdp', 'network', 'zeroconf', 'usb', 'webhook', 'homeassistant', 'websocket_api', 'bluetooth', 'cloud', 'api', 'http'}
2023-05-02 10:12:18.373 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'input_number', 'input_button', 'schedule', 'mysensors', 'nmap_tracker', 'tag', 'person', 'cover', 'device_tracker', 'yamaha_musiccast', 'persistent_notification', 'auth', 'bluetooth_adapters', 'stt', 'vacuum', 'shell_command', 'broadlink', 'homekit_controller', 'application_credentials', 'config', 'fullykiosk', 'derivative', 'image_upload', 'ios', 'automation', 'radio_browser', 'file_upload', 'brother', 'sensor', 'stream', 'group', 'fritz', 'diagnostics', 'tado', 'tts', 'media_source', 'input_text', 'pyscript', 'energy', 'generic', 'switch_as_x', 'counter', 'mqtt', 'watchman', 'hacs', 'my', 'conversation', 'analytics', 'intent_script', 'camera', 'tplink', 'weather', 'openweathermap', 'blueprint', 'powercalc', 'garbage_collection', 'season', 'reolink', 'adaptive_lighting', 'cpuspeed', 'light', 'switch', 'ffmpeg', 'history', 'monitor_docker', 'input_boolean', 'map', 'onvif', 'timer', 'select', 'androidtv', 'mobile_app', 'tractive', 'input_datetime', 'sensirion_ble', 'transmission', 'template', 'media_player', 'input_select', 'snips', 'smartir', 'moon', 'system_health', 'script', 'ifttt', 'matter', 'climate', 'rfxtrx', 'image_processing', 'nina', 'python_script', 'tautulli', 'wled', 'hardware', 'notify', 'owntracks', 'backup', 'repairs', 'glances', 'homeassistant_alerts', 'uptime', 'ld2410_ble', 'proximity', 'sun', 'trace', 'mjpeg', 'integration', 'holidays', 'sql', 'thermal_comfort', 'plex', 'geofency', 'battery_consumption', 'alexa_media', 'homekit', 'binary_sensor', 'scene', 'discovery', 'composite', 'device_automation', 'onboarding', 'google', 'assist_pipeline', 'logbook', 'fan', 'esphome', 'lovelace', 'apcupsd', 'dwd_weather', 'utility_meter', 'iaquk', 'zone', 'rest_command', 'apple_tv', 'search'}
jbouwh commented 1 year ago

You can look for any dependencies in the manifest file.

diplix commented 1 year ago

thanks for the clue. if i look into owntracks manifest file, i see:

"after_dependencies": ["mqtt"]

if i look into snips manifest file there’s no after_dependencies, but only "dependencies": ["mqtt"],

might that be the reason snips is not initializing without the explicit check for mqtt?

jbouwh commented 1 year ago

@diplix May be you can check the startup time of owntracks?

diplix commented 1 year ago

i have one more integration that directly utilizes mqtt: owntracks no problems initializing here, reported startup time for owntracks is a mere 0.31 seconds.

diplix commented 1 year ago

@jbouwh what do you think of my question/sugestion that the snips manifest file should contain

"after_dependencies": ["mqtt"],

instead of

"dependencies": ["mqtt"],

wouldn’t that explain the problem?

jbouwh commented 1 year ago

@jbouwh what do you think of my question/sugestion that the snips manifest file should contain

"after_dependencies": ["mqtt"],

instead of

"dependencies": ["mqtt"],

wouldn’t that explain the problem?

I am not sure, but you could try it perhaps by changing the snips manifest. @bdraco What do you think?

diplix commented 1 year ago

i can try that, remove the explicit check for mqtt and change the snips manifest to see if that enables snips to initialize correctly.

diplix commented 1 year ago

yes, snips initializes with this snips manifest file

{
  "domain": "snips",
  "name": "Snips",
  "codeowners": [],
  "after_dependencies": ["mqtt"],
  "documentation": "https://www.home-assistant.io/integrations/snips",
  "iot_class": "local_push"
}

https://github.com/home-assistant/core/pull/91790 can be re-applied.

jbouwh commented 1 year ago

So what you say is that when mqtt is the after_dependencies, it is set up before snips. If it is in dependencies it needs the waiting because mqtt is not initialized yet?

diplix commented 1 year ago

i guess thats what i said, or rather what i observed. however i am not a developer or coder and am not really able to explain to you how dependencies and after_dependencies differ or work in detail.

so: 1) it works as intented if i apply the changes i described 2) i observed that the mysensors integration that has "after_dependencies": ["mqtt"], in it’s manifest file and according to the logs will wait for after dependencies ['mqtt'] 3) so i guess that after_dependencies in a manifest file indicates that the integration wil wait for the listed dependencies before it initializes.

jbouwh commented 1 year ago

That is correct. I have not a sharp view on what the actual differences are.

De documentation does not make it clearer to me.

https://developers.home-assistant.io/docs/creating_integration_manifest/

It seems there is an issue in handling the dependencies, not sure why this happens yet.

jbouwh commented 1 year ago

@diplix could you share some (redacted) debug logging or your startup where snips is having mqtt in dependencies but where mqtt was not set up before snips is initialized?

diplix commented 1 year ago

It seems there is an issue in handling the dependencies, not sure why this happens yet.

what makes you think that there’s an issue, if after-dependencies does work as intented?

i just had a quick look at the codebase. async_set_domains_to_be_loaded seems to handle loading the dependencies and handles after_dependencies: https://github.com/home-assistant/core/blob/ef9bcd9285980385eede726e15aa1e7d20238eee/homeassistant/setup.py#L66-L71

and this loop, that iterates over integration.after_dependencies does exactly what in this case needs: waiting:

https://github.com/home-assistant/core/blob/ef9bcd9285980385eede726e15aa1e7d20238eee/homeassistant/setup.py#L122-L127

the loop that iterates over integration.dependencies does not wait for anything, but only checks:

https://github.com/home-assistant/core/blob/ef9bcd9285980385eede726e15aa1e7d20238eee/homeassistant/setup.py#L114-L118

why not ask someone who does have „a sharp view on what the actual differences are“ instead of speculating about a bug?

another clue is this PR: https://github.com/home-assistant/core/pull/68744

Use after_dependencies to wait for platforms to be set up.

and thats exactly what the snips integration needed: wait for the mqtt platform to be set up.(handled by the core, instead of the integration itself).

jbouwh commented 1 year ago

Thnx, I do have contact with @bdraco on this. It seems you are right. We do not add a wait task for dependencies, only for after dependencies if you look at the code, that would indeed explain it.

jbouwh commented 1 year ago

What happens is that async_setup is awaited for, but not async_setup_entry. There were recent changes where we do not use async_setup anymore. The after_dependencies might work, but only if mqtt was set up manually and mqtt is optional. So for snips the added check is a good solution. The dependency will make sure mqtt is set up or the integration with the dependency will fail.

jbouwh commented 1 year ago

https://github.com/home-assistant/core/pull/92524 was opened to ensure we wait for the MQTT client in similar cases.