MQTT: "Timed out waiting for mid" never recovers leaves MQTT dead

[decairn]

The problem

On HA restart, gets "Timed out waiting for mid XXX" 170 times appears in log.
Devices controlled via MQTT do not respond, do not have current state shown.

Environment

System Health

version: 2021.1.1
installation_type: Home Assistant OS
dev: false
hassio: true
docker: true
virtualenv: false
python_version: 3.8.7
os_name: Linux
os_version: 5.4.79-v7
arch: armv7l
timezone: America/Los_Angeles

GitHub API: ok
Github API Calls Remaining: 4685
Installed Version: 1.9.0
Stage: running
Available Repositories: 713
Installed Repositories: 14

logged_in: true
subscription_expiration: February 8, 2021, 4:00 PM
relayer_connected: true
remote_enabled: false
remote_connected: false
alexa_enabled: false
google_enabled: true
can_reach_cert_server: ok
can_reach_cloud_auth: ok
can_reach_cloud: ok

host_os: Home Assistant OS 5.10
update_channel: stable
supervisor_version: 2020.12.7
docker_version: 19.03.13
disk_total: 57.8 GB
disk_used: 6.5 GB
healthy: true
supported: true
board: rpi3
supervisor_api: ok
version_api: ok
installed_addons: Samba share (9.3.0), Check Home Assistant configuration (3.6.0), Mosquitto broker (5.1), Terminal & SSH (8.10.0)

dashboards: 1
mode: storage
views: 10
resources: 11

• Home Assistant Core release with the issue:
• Last working Home Assistant Core release (if known):
• Operating environment (OS/Container/Supervised/Core):
• Integration causing this issue:
• Link to integration documentation on our website:

Problem-relevant configuration.yaml

Traceback/Error logs

2021-01-10 18:56:24 ERROR (MainThread) [homeassistant.components.mqtt] Timed out waiting for mid 162

Additional information

zwavejs2mqtt is used, that runs on another host. Use of MQTT is new, no other services other than zwavejs use it so all activity is to that integration. Physically 30 devices to zwave.
In normal runtime outside of restart, the HA RPi3+ has load < .2, on restart is jumps to .5 for a few minutes.
I've looked at old issues with same error, doesn't appear to be anything I can directly configure to increase timeouts? (e.g. #39847)

[probot-home-assistant]

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

[probot-home-assistant]

Hey there @home-assistant/core, @emontnemery, mind taking a look at this issue as its been labeled with an integration (mqtt) you are listed as a codeowner for? Thanks!
_{^{(message by CodeOwnersMention)}}

[emontnemery]

"Timed out waiting for mid" means there was no ACK from MQTT server.
Do devices controlled by MQTT ever work, or not at all?

[decairn]

If I leave it it may come back, I have not determined the time period yet other than maybe 1 hour-ish but sometimes it just doesn't come back and I get to try a reboot again. I've turned on MQTT logging now and will monitor, hopefully get something more concrete on things.

[decairn]

I've nuked the MQTT install with move to zwavejs websockets. Closing N/A.

[adamoutler]

Why close this issue? There are still users looking for solutions. The issue is not solved and zwavejs is not ready for prime time yet.

My logs show I have 3k occurrences.

Logger: homeassistant.components.mqtt
Source: components/mqtt/__init__.py:934
Integration: MQTT (documentation, issues)
First occurred: 11:39:46 AM (3031 occurrences)
Last logged: 11:47:44 AM

Timed out waiting for mid 6374
Timed out waiting for mid 6375
Timed out waiting for mid 6376
Timed out waiting for mid 6377
Timed out waiting for mid 6378

[emontnemery]

@adamoutler can you please give some more information about your setup, and if you have any problems with MQTT except for the errors in the log?

[adamoutler]

Hi @emontnemery, I am using HassOS, with OZW Beta and MQTT Plugin. I don't know what these errors are, but I'm always up-to-date with the latest builds of HassOS and addons. I don't know how to detect issues with MQTT. I just updated everything and restarted. these items are found in my logs

[emontnemery]

What kind of hardware are you running HassOS on?
Do you continuously get more of the errors, are do they seem to be more common for example just after a restart?

Edit:
The errors mean that Home Assistant didn't get a reply from the MQTT server within 10s when attempting to subscribe to a topic or send a message.

[adamoutler]

I'm running on Raspberry Pi 4. I get thousands of these over time. Seems relatively quiet today, but as you can see from earlier, they build up to 3k+.

[adamoutler]

The errors mean that Home Assistant didn't get a reply from the MQTT server within 10s when attempting to subscribe to a topic or send a message.

This would be much more helpful as a message rather than "Timeout waiting for mid 4".

[isabellaalstrom]

I'm having similar problems. Do not run ozw2mqtt. Do not only happen at startup. I'm running mqtt official addon on hassos in a vm.
First I get this

Logger: paho.mqtt.client
Source: /usr/local/lib/python3.8/site-packages/paho/mqtt/client.py:2404
First occurred: 2:34:23 PM (1 occurrences)
Last logged: 2:34:23 PM

failed to receive on socket: [Errno 104] Connection reset by peer

then

Logger: homeassistant.components.mqtt
Source: components/mqtt/__init__.py:934
Integration: MQTT (documentation, issues)
First occurred: 2:39:37 PM (60 occurrences)
Last logged: 2:39:49 PM

Timed out waiting for mid 355
Timed out waiting for mid 356
Timed out waiting for mid 357
Timed out waiting for mid 358
Timed out waiting for mid 359

During this no mqtt devices are available in hass. They eventually come back on their own.

[emontnemery]

@adamoutler good point, will adjust the error message :)

[emontnemery]

@isabellaalstrom Right, so that HA means lost the connection to the MQTT server entirely. Do you have some logs from the official addon?

[isabellaalstrom]

@emontnemery I saw stuff in the logs when I looked at this, but they are too far behind now to see them on the addon page. Is there a way to get more of the log than what is showed there?

[emontnemery]

I'm not sure, I'd suggest to open an issue on https://github.com/home-assistant/addons/issues

[isabellaalstrom]

I saw this issue there, so I built on: home-assistant/addons#1817

[anubisg1]

i have the same exact issue and running HASS.IO as a VM on synology NAS.

[LifeBandit666]

Same issue here using mosquito and Zigbee2mqtt

[Automot360]

Have the same issue and running HASS.IO as a VM on Synology NAS.

[anubisg1]

i gave up, nobody is looking into this. i moved mosquitto to an external docker container and it works like a charm

[emontnemery]

The problem is with the add-on, there's not really anything to do about it in Home Assistant core. I suggest we close this issue.

[adamoutler]

Maybe link to the issue raised with the addon and then close? I'm not sure if it's the MQTT or the MQTT device Addon. It's odd that it seems to always appear in 4's which would suggest something. Im not sure what is suggested though.

[emontnemery]

@adamoutler I meant this issue which @isabellaalstrom linked to: home-assistant/addons#1817, also things got worse in the latest update: home-assistant/addons#1887

[seaniedan]

This error appears for me when I try to listen to topics on the MQTT server in HA. I try to listen to #, but no messages appear, then I look in the logs and see:

2021-05-06 21:19:48 WARNING (Thread-5) [homeassistant.components.mqtt] Disconnected from MQTT server core-mosquitto:1883 (1)
2021-05-06 21:21:04 WARNING (Thread-5) [homeassistant.components.mqtt] Disconnected from MQTT server core-mosquitto:1883 (1)
2021-05-06 21:22:37 WARNING (Thread-5) [homeassistant.components.mqtt] Disconnected from MQTT server core-mosquitto:1883 (1)
2021-05-06 21:24:41 WARNING (Thread-5) [homeassistant.components.mqtt] Disconnected from MQTT server core-mosquitto:1883 (1)
2021-05-06 21:27:37 WARNING (MainThread) [homeassistant.components.mqtt] No ACK from MQTT server in 10 seconds (mid: 211)
2021-05-06 21:27:37 WARNING (MainThread) [homeassistant.components.mqtt] No ACK from MQTT server in 10 seconds (mid: 212)
2021-05-06 21:27:37 WARNING (MainThread) [homeassistant.components.mqtt] No ACK from MQTT server in 10 seconds (mid: 213)
2021-05-06 21:27:37 WARNING (MainThread) [homeassistant.components.mqtt] No ACK from MQTT server in 10 seconds (mid: 214)
...
MQTT is the backbone of HomeAssistant for me, so it's important this is fixed! Currently I'm using metric2mqtt and espruinohub, via the Eclipse Mosquito add on in HA. Any help welcomed, happy to help debug.

[thecode]

This should be fixed by: home-assistant/addons#2007