Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Dependency for mqtt component does not work as expected #92297

Closed
jbouwh opened this issue Apr 30, 2023 · 32 comments · Fixed by home-assistant/developers.home-assistant#1768 or #92524
Closed

Comments

@jbouwh
Copy link
Contributor

jbouwh commented Apr 30, 2023

The problem

Change #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 #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
Copy link

@home-assistant
Copy link

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
Copy link
Contributor

diplix commented Apr 30, 2023

@jbouwh asked in #92236 (comment)

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
Copy link
Contributor Author

jbouwh commented Apr 30, 2023

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
Copy link
Contributor Author

jbouwh commented Apr 30, 2023

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
Copy link
Contributor

diplix commented May 1, 2023

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
Copy link
Contributor Author

jbouwh commented May 1, 2023

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
Copy link
Contributor

diplix commented May 1, 2023

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
Copy link

home-assistant bot commented May 1, 2023

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
Copy link
Contributor Author

jbouwh commented May 1, 2023

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
Copy link
Contributor Author

jbouwh commented May 1, 2023

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
Copy link
Contributor Author

jbouwh commented May 1, 2023

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

@diplix
Copy link
Contributor

diplix commented May 1, 2023

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
Copy link
Contributor

diplix commented May 1, 2023

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
Copy link
Contributor Author

jbouwh commented May 1, 2023

Do you have any custom integrations set up?

@diplix
Copy link
Contributor

diplix commented May 2, 2023

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
Copy link
Contributor Author

jbouwh commented May 2, 2023

You can look for any dependencies in the manifest file.

@diplix
Copy link
Contributor

diplix commented May 3, 2023

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
Copy link
Contributor Author

jbouwh commented May 3, 2023

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

@diplix
Copy link
Contributor

diplix commented May 3, 2023

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
Copy link
Contributor

diplix commented May 3, 2023

@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
Copy link
Contributor Author

jbouwh commented May 3, 2023

@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
Copy link
Contributor

diplix commented May 3, 2023

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
Copy link
Contributor

diplix commented May 3, 2023

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"
}

#91790 can be re-applied.

@jbouwh
Copy link
Contributor Author

jbouwh commented May 3, 2023

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
Copy link
Contributor

diplix commented May 3, 2023

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
Copy link
Contributor Author

jbouwh commented May 3, 2023

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
Copy link
Contributor Author

jbouwh commented May 3, 2023

@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
Copy link
Contributor

diplix commented May 4, 2023

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:

This allow us to:
- Properly handle after_dependencies.
- Keep track of domains which will load but have not yet finished loading
"""
hass.data.setdefault(DATA_SETUP_DONE, {})
hass.data[DATA_SETUP_DONE].update({domain: asyncio.Event() for domain in domains})

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

core/homeassistant/setup.py

Lines 122 to 127 in ef9bcd9

for dep in integration.after_dependencies:
if (
dep not in dependencies_tasks
and dep in to_be_loaded
and dep not in hass.config.components
):

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

core/homeassistant/setup.py

Lines 114 to 118 in ef9bcd9

dependencies_tasks = {
dep: hass.loop.create_task(async_setup_component(hass, dep, config))
for dep in integration.dependencies
if dep not in hass.config.components
}

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: #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
Copy link
Contributor Author

jbouwh commented May 4, 2023

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
Copy link
Contributor Author

jbouwh commented May 4, 2023

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
Copy link
Contributor Author

jbouwh commented May 4, 2023

#92524 was opened to ensure we wait for the MQTT client in similar cases.

@github-actions github-actions bot locked and limited conversation to collaborators Jun 3, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.