Race condition mqtt_statestream

[francisp2]

The problem

MQTT is running, but it seems mqtt_statestream wants to run before mqtt.

(I did not have this in 2024.6.0b4) 2024-06-06 16:44:38.986 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration localtuya 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 2024-06-06 16:44:39.009 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration esp_wd 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 2024-06-06 16:44:39.041 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration spook 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 2024-06-06 16:44:39.074 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration afvalbeheer 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 2024-06-06 16:44:39.111 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration 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 2024-06-06 16:44:39.160 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration tuya_ble 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 2024-06-06 16:44:39.193 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration spook_inverse 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 2024-06-06 16:46:29.462 ERROR (MainThread) [homeassistant.components.mqtt_statestream] MQTT integration is not available 2024-06-06 16:46:29.463 ERROR (MainThread) [homeassistant.setup] Setup failed for 'mqtt_statestream': Integration failed to initialize.

log file with mqtt debug enabled:

home-assistant.log.txt

What version of Home Assistant Core has the issue?

2024.6.0 and 2024.6.1

What was the last working version of Home Assistant Core?

2024.6.0b4

What type of installation are you running?

Home Assistant Supervised

Integration causing the issue

mqtt statestream

Link to integration documentation on our website

https://www.home-assistant.io/integrations/mqtt_statestream/

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

mqtt_statestream documentation mqtt_statestream source

[home-assistant[bot]]

Hey there @emontnemery, @jbouwh, @bdraco, 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. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

---

mqtt documentation mqtt source _{^{(message by IssueLinks)}}

[bdraco]

Does this happen every time or only sometimes?

If you turn on debug logging for mqtt, do you see the mqtt connection being established too late and it timing out?

[bdraco]

I see you have a debug log attached with mqtt debugging turned on. Looking at that now

[bdraco]

2024-06-08 06:27:29.975 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration spook_inverse 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
2024-06-08 06:29:07.572 ERROR (MainThread) [homeassistant.components.mqtt_statestream] MQTT integration is not available
2024-06-08 06:29:07.573 ERROR (MainThread) [homeassistant.setup] Setup failed for 'mqtt_statestream': Integration failed to initialize.
2024-06-08 06:29:15.582 DEBUG (MainThread) [homeassistant.components.mqtt.client] 10.0.0.63: connection opened 18

It does look like its taking 166 seconds for mqtt to connect after startup.

The timeout is 30 seconds. https://github.com/home-assistant/core/blob/e4be3d8435c37177ca206232e1c765b97977d2bb/homeassistant/components/mqtt/util.py#L37 https://github.com/home-assistant/core/blob/e4be3d8435c37177ca206232e1c765b97977d2bb/homeassistant/components/mqtt/util.py#L120

It also looks like mqtt_statestream is taking a while to wait as well.

It might be that the event loop is being blocked by another integration which is starving mqtt for run time so it times out before it can start

[bdraco]

Would you please try starting up in debug mode

https://community.home-assistant.io/t/2024-5-tracking-down-instability-issues-caused-by-integrations/724441

If that doesn't find anything you might need to go the debugpy: option.

Can you also post a bit more about the hardware being used? The numbers look like a very low powered machine but that may be the event loop being blocked that is hampering the performance.

[francisp2]

I set debug to true home-assistant.log.txt

It is a Pi 2

It only happens on the install of a new version, a regular reboot works fine.

[bdraco]

It looks like its 2s too late

2024-06-25 18:14:56.102 ERROR (MainThread) [homeassistant.components.mqtt_statestream] MQTT integration is not available
2024-06-25 18:14:56.103 ERROR (MainThread) [homeassistant.setup] Setup failed for 'mqtt_statestream': Integration failed to initialize.
2024-06-25 18:15:54.978 DEBUG (MainThread) [homeassistant.components.mqtt.client] 10.0.0.63: connection opened 17
2024-06-25 18:15:54.979 DEBUG (MainThread) [homeassistant.components.mqtt.client] 10.0.0.63: Starting client misc loop
2024-06-25 18:15:54.981 DEBUG (MainThread) [homeassistant.components.mqtt.client] 10.0.0.63: register write 17
2024-06-25 18:15:55.656 DEBUG (MainThread) [homeassistant.components.mqtt.client] 10.0.0.63: unregister write 17
2024-06-25 18:15:55.682 DEBUG (MainThread) [homeassistant.components.mqtt.client] Connected to MQTT server 10.0.0.63:1883 (0)

Maybe the timeout is just too low for an RPI2

[bdraco]

maybe going to 45s is enough

diff --git a/homeassistant/components/mqtt/util.py b/homeassistant/components/mqtt/util.py
index 97fa616fdd1..1020570fd47 100644
--- a/homeassistant/components/mqtt/util.py
+++ b/homeassistant/components/mqtt/util.py
@@ -36,7 +36,7 @@ from .const import (
 )
 from .models import DATA_MQTT, DATA_MQTT_AVAILABLE, ReceiveMessage

-AVAILABILITY_TIMEOUT = 30.0
+AVAILABILITY_TIMEOUT = 45.0

 TEMP_DIR_NAME = f"home-assistant-{DOMAIN}"

[jbouwh]

maybe going to 45s is enough

diff --git a/homeassistant/components/mqtt/util.py b/homeassistant/components/mqtt/util.py
index 97fa616fdd1..1020570fd47 100644
--- a/homeassistant/components/mqtt/util.py
+++ b/homeassistant/components/mqtt/util.py
@@ -36,7 +36,7 @@ from .const import (
 )
 from .models import DATA_MQTT, DATA_MQTT_AVAILABLE, ReceiveMessage

-AVAILABILITY_TIMEOUT = 30.0
+AVAILABILITY_TIMEOUT = 45.0

 TEMP_DIR_NAME = f"home-assistant-{DOMAIN}"

May be just change it to 60 seconds?

[bdraco]

maybe going to 45s is enough

diff --git a/homeassistant/components/mqtt/util.py b/homeassistant/components/mqtt/util.py
index 97fa616fdd1..1020570fd47 100644
--- a/homeassistant/components/mqtt/util.py
+++ b/homeassistant/components/mqtt/util.py
@@ -36,7 +36,7 @@ from .const import (
 )
 from .models import DATA_MQTT, DATA_MQTT_AVAILABLE, ReceiveMessage

-AVAILABILITY_TIMEOUT = 30.0
+AVAILABILITY_TIMEOUT = 45.0

 TEMP_DIR_NAME = f"home-assistant-{DOMAIN}"

May be just change it to 60 seconds?

I think we start warning if something takes more than 60s, so maybe go with 50s to avoid the warning?