MQTT integration Unsubscribing from

tgermain · October 22, 2020, 5:36pm

Hello,

since today beginning of the afternoon, i’m encountering really really annoying issue with MQTT integration.

The integration is configured for ages now (first from yaml, and now from UI directly). Everything is working fine (sometimes for 1h, sometimes for 2h…) and at some point, the integration is unsubscribing from all my devices:

2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff7_th10/tele/SENSOR, mid: 223
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_1/tele/HASS_STATE, mid: 224
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_1/tele/SENSOR, mid: 225
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_1/tele/HASS_STATE, mid: 226
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_2/tele/HASS_STATE, mid: 227
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_3/tele/HASS_STATE, mid: 228
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoffth10_1/tele/SENSOR, mid: 229
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoffth10_1/tele/HASS_STATE, mid: 230
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tasmota/tele/HASS_STATE, mid: 231
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_7/tele/HASS_STATE, mid: 232
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_8/tele/HASS_STATE, mid: 233
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_9/tele/HASS_STATE, mid: 234
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_5/tele/HASS_STATE, mid: 235
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_4/tele/HASS_STATE, mid: 236
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_3/tele/HASS_STATE, mid: 237
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_12B210/HASS_STATE, mid: 238
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff6_s26/tele/HASS_STATE, mid: 239
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff7_th10/tele/HASS_STATE, mid: 240
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26C2BC/SENSOR, mid: 241
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26C2BC/HASS_STATE, mid: 242
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26DD0B/SENSOR, mid: 243
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26DD0B/HASS_STATE, mid: 244
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from zigbee2mqtt/Porte abri jardin, mid: 245
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from zigbee2mqtt/Porte tondeuse, mid: 246
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from zigbee2mqtt/Luminosité, mid: 247
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from zigbee2mqtt/living_room_lamp, mid: 248
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff2_basic/tele/STATE, mid: 249
2020-10-22 19:15:58 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff2_basic/tele/LWT, mid: 250
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_12B210/STATE, mid: 251
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_12B210/LWT, mid: 252
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff6_s26/tele/STATE, mid: 253
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff6_s26/tele/LWT, mid: 254
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff7_th10/tele/STATE, mid: 255
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff7_th10/tele/LWT, mid: 256
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff1_basic/tele/STATE, mid: 257
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoff1_basic/tele/LWT, mid: 258
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_1/tele/STATE, mid: 259
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_1/tele/LWT, mid: 260
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_1/tele/STATE, mid: 261
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_1/tele/LWT, mid: 262
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_2/tele/STATE, mid: 263
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_2/tele/LWT, mid: 264
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_3/tele/STATE, mid: 265
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_3/tele/LWT, mid: 266
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoffth10_1/tele/STATE, mid: 267
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from sonoffth10_1/tele/LWT, mid: 268
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tasmota/tele/STATE, mid: 269
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tasmota/tele/LWT, mid: 270
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_7/tele/STATE, mid: 271
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_7/tele/LWT, mid: 272
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_8/tele/STATE, mid: 273
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_8/tele/LWT, mid: 274
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_9/tele/STATE, mid: 275
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_9/tele/LWT, mid: 276
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_5/tele/STATE, mid: 277
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_5/tele/LWT, mid: 278
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_4/tele/STATE, mid: 279
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from shelly1_4/tele/LWT, mid: 280
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_3/tele/STATE, mid: 281
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from bw_shp6_3/tele/LWT, mid: 282
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26C2BC/STATE, mid: 283
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26C2BC/LWT, mid: 284
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26DD0B/STATE, mid: 285
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from tele/tasmota_26DD0B/LWT, mid: 286
2020-10-22 19:15:59 DEBUG (MainThread) [homeassistant.components.mqtt] Unsubscribing from zigbee2mqtt/Prise voiture, mid: 287

And all related entities become unavailable. I already checked devices and they keep sending their state/status without any issue.

I don’t have any useful log from mqtt broker addon.

I’m running hassio (on a raspberry pi 3B, hassos 4.41 and supervisor 249).

I only found two solution to temporary fix the issue:

publish 1 on topic cmnd/tasmotas/SetOption19 and devices reappears for some times
Restarting the broker

Anyone has the same issue ? Any solution to fix that ?

Thanks !

Thomas

tom_l · October 22, 2020, 5:55pm

I don’t think I’ve ever seen that happen before
Are you using the mosquitto addon?
If so check the logs on the addon page and probably the supervisor logs too.

tgermain · October 22, 2020, 6:03pm

Thanks for your reply.

yes i’m using the mosquitto addon. no useful logs from there, last log is 2h before unsubscribing occurs:
1603389525: Saving in-memory database to /data/mosquitto.db.

Same for supervisor, last log is 2h old

This is really annoying, this is killing almost 150 entities, and also killing most of my automations

EDIT: by the way, is there any way to have some debug log from mosquitto addon ?

Botervloot · October 24, 2020, 9:09am

When in settings > integrations > MQTT > Configure, does subscribing to wildcard topic ‘#’ get it to magically start running again for you too?

tgermain · October 24, 2020, 9:24am

Hmm sounds interesting, It just crashed again today at ~10am. So I will wait until it crashes again.

But do you have to do that everytime after it crashes ?

Botervloot · October 24, 2020, 9:58am

I’m also having issues with MQT since yesterday and couldn’t figure out why it wasn’t working and why doing this fixed it. Have to wait until it crashes again to chekc if my logs mirror yours

tgermain · October 24, 2020, 9:59am

wait and see

tgermain · October 24, 2020, 11:17am

It just crashed again, and indeed subscribing to # made it working again, but I think it won’t prevent the unsubscribing

Botervloot · October 24, 2020, 12:26pm

Okay, it seems like we have the same issue then. And you’re right, it won’t prevent the issue from happening again…

tgermain · October 24, 2020, 1:42pm

yes, this is really annoying, I created an issue: https://github.com/home-assistant/core/issues/42285

tgermain · October 25, 2020, 6:36pm

@Botervloot see issue https://github.com/home-assistant/core/issues/42285. For me, this is happening when I’m reloading the mqtt entities.

tom_l · October 25, 2020, 6:43pm

Ah! The reload is doing it. Well spotted and good to see you created an issue and the dev’s are onto it already.

Botervloot · October 25, 2020, 9:07pm

I was waiting for it to crash again to check the logs, but that strangely hasn’t happened yet.

Reloading does break my MQTT too, but not consistently. I also don’t use discovered entities, all are created manually in yaml. I also can’t reproduce the same unsubscribing wave you found. This leads me to believe that our issues are somewhat similar but also different.

It’s a really weird issue. When I reload my MQTT entities from the ui, their state keeps bouncing back and forth between available and their actual state for about 15 times in a few seconds. Some of my automations for lights are setup with state change as trigger, so the rapid switching makes for some… interesting lighting effects…!
image|403x500

Further investigation and tailing the logs reveals a MASSIVE amount of automations getting triggered and throwing errors because they are already running. I believe this to be partly a result of the scale of my MQTT setup (+/- 250 devices?), which all use the same availability topic. When the integration can’t keep up after reloading, it keeps missing this one LWT message, which changes the state of ALL MQTT devices to unavailable, which triggers all automations triggers by state change, which causes the system to slow down more and repeat itself. I’ve never noticed this issue before this week. It’s also strange that it does manage to get out of it’s loop after a few minutes with a working MQTT integration, but other times it doesn’t. What’s even stranger is why manually subscribing fixes the problem within seconds…?

What I’ve noticed about the integration is that for all 250 devices using the same availability topic, it (re?)subscribes to that same topic, which seems excessive. Automations also seem to be triggered by the state ‘unavailable’, which seems unintended to me. I’ll have to do some more research to find my exact cause and fix.

tgermain · October 25, 2020, 9:39pm

I was also waiting for a crash, but nothing happens until I reload mqtt. Maybe you have the same problem as me ?

I have the same effect with automations, some are triggered on state changed (I have some triggers like > 10 or so) which IHMO should not be triggered, but I think this is another story.

I think you should have a look at the issue, you could probably give more help than I can.

Botervloot · October 25, 2020, 11:08pm

Yes, I’m folowing the issue on github