Race condition mqtt_statestream about core

[home-assistant]

mqtt_statestream documentation
mqtt_statestream source

[home-assistant]

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.

core/homeassistant/components/mqtt/util.py

Line 37 in e4be3d8

AVAILABILITY_TIMEOUT = 30.0

core/homeassistant/components/mqtt/util.py

Line 120 in e4be3d8

async with asyncio.timeout(AVAILABILITY_TIMEOUT):

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