mqtt: Exception in availability_message_received #40166

andriej · 2020-09-17T10:53:14Z

The problem

While upgrading my zigbee sitck I did shutdown zigbee2mqtt add-on and found out this spam in log:

Logger: homeassistant.util.logging
Source: util/logging.py:108
First occurred: 12:13:16 (404 occurrences)
Last logged: 12:18:51

Exception in availability_message_received when handling msg on 'zigbee2mqtt/bridge/state': 'offline' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper msg_callback(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/__init__.py", line 1076, in availability_message_received if msg.payload == self._avail_topics[topic][CONF_PAYLOAD_AVAILABLE]: KeyError: 'zigbee2mqtt/bridge/state'
Exception in availability_message_received when handling msg on 'zigbee2mqtt/bridge/state': 'online' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper msg_callback(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/__init__.py", line 1076, in availability_message_received if msg.payload == self._avail_topics[topic][CONF_PAYLOAD_AVAILABLE]: KeyError: 'zigbee2mqtt/bridge/state'

Environment

Home Assistant Core release with the issue: 0.114.4
Last working Home Assistant Core release (if known): n/a
Operating environment (OS/Container/Supervised/Core): Supervised Debian 10 Buster
Integration causing this issue: mqtt
Link to integration documentation on our website: https://www.home-assistant.io/integrations/mqtt/

Problem-relevant `configuration.yaml`

n/a

Traceback/Error logs

2020-09-17 12:18:51 ERROR (MainThread) [homeassistant.util.logging] Exception in availability_message_received when handling msg on 'zigbee2mqtt/bridge/state': 'online'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/__init__.py", line 1076, in availability_message_received
    if msg.payload == self._avail_topics[topic][CONF_PAYLOAD_AVAILABLE]:
KeyError: 'zigbee2mqtt/bridge/state'

2020-09-17 12:18:51 ERROR (MainThread) [homeassistant.util.logging] Exception in availability_message_received when handling msg on 'zigbee2mqtt/bridge/state': 'online'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/__init__.py", line 1076, in availability_message_received
    if msg.payload == self._avail_topics[topic][CONF_PAYLOAD_AVAILABLE]:
KeyError: 'zigbee2mqtt/bridge/state'

2020-09-17 12:18:51 ERROR (MainThread) [homeassistant.util.logging] Exception in availability_message_received when handling msg on 'zigbee2mqtt/bridge/state': 'online'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/__init__.py", line 1076, in availability_message_received
    if msg.payload == self._avail_topics[topic][CONF_PAYLOAD_AVAILABLE]:
KeyError: 'zigbee2mqtt/bridge/state'

2020-09-17 12:18:51 ERROR (MainThread) [homeassistant.util.logging] Exception in availability_message_received when handling msg on 'zigbee2mqtt/bridge/state': 'online'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper
    msg_callback(msg)
  File "/usr/src/homeassistant/homeassistant/components/mqtt/__init__.py", line 1076, in availability_message_received
    if msg.payload == self._avail_topics[topic][CONF_PAYLOAD_AVAILABLE]:
KeyError: 'zigbee2mqtt/bridge/state'

404 times...

Additional information

Right now I still have MQTT in yaml as previous issue is still valid - I don't know if it's possible to migrate MQTT flawlessly to configflow.
#39860

The text was updated successfully, but these errors were encountered:

probot-home-assistant · 2020-09-17T11:01:38Z

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

probot-home-assistant · 2020-09-17T11:04:40Z

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 · 2020-09-17T11:15:07Z

Please enable MQTT debug logging and share a log from HA startup until the issue is reproduced.

Log settings:

 logger:
   default: info
   logs:
     homeassistant.core: debug
     homeassistant.components.mqtt: debug

andriej · 2020-09-17T11:25:15Z

Unfortunately I wasn't able to reproduce error - both turning Z2M off and reinstalling it twice.
I'm not sure what caused this to happen.

While you're on it - could you please also take a look @ issue linked in "Additional info"?
I'm able to reproduce it every time.

emontnemery · 2020-09-17T14:07:48Z

This could be a problem related to MQTT discovery update, but it's a bit tricky to debug without a log.

Do you know if zigbee2mqtt has implemented support for multiple availability topics as suggested here: Koenkk/zigbee2mqtt#775 (comment)

andriej · 2020-09-17T14:12:36Z

It seems it did, as I can have 'unavailable' on zigbee nodes that are out of range while all others are available and working.

emontnemery · 2020-09-17T14:15:43Z

OK, but the code doesn't seem to be updated to support both:
https://github.com/Koenkk/zigbee2mqtt/blob/c0faae73bbd1185c5b06739718360776ae88ab23/lib/extension/homeassistant.js#L2225-L2232

Have you enabled zigbee2mqtt's availability timeout: https://www.zigbee2mqtt.io/information/availability.html ?

andriej · 2020-09-17T14:16:15Z

Maybe you have enabled zigbee2mqtt's availability timeout: https://www.zigbee2mqtt.io/information/availability.html ?

Yes, I did.

emontnemery · 2020-09-17T14:16:59Z

OK, did you recently enable that option, without restarting HA?

andriej · 2020-09-17T14:18:41Z

I've enabled it yesterday and it's possible I didn't restart in meanwhile, yes.

emontnemery · 2020-09-17T14:21:22Z

OK, can you then try to reproduce the problem by:

Enable MQTT debug log
Disable the availability option again in zigbee2mqtt
Restart HA
Enable the availability option again in zigbee2mqtt

This will trigger an attempt by zigbee2mqtt to reconfigure the availability settings on HA side, which may be triggering the exceptions.

andriej · 2020-09-17T14:31:29Z

I've tried these steps, for one of sensors similiar error occured. Full log from few seconds before and after: https://pastebin.com/pRbWHdix

Logger: homeassistant.util.logging
Source: util/logging.py:108
First occurred: 16:28:34 (3 occurrences)
Last logged: 16:28:40

Exception in state_message_received when handling msg on 'zigbee2mqtt/Xiaomi Door Pokój Mniejszy Uchylenie': '{"battery":100,"contact":false,"linkquality":95,"voltage":3025}' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper msg_callback(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/binary_sensor.py", line 190, in state_message_received payload = value_template.async_render_with_possible_json_value( File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 274, in async_render_with_possible_json_value self._ensure_compiled() File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 300, in _ensure_compiled assert self.hass is not None, "hass variable not set on template" AssertionError: hass variable not set on template
Exception in state_message_received when handling msg on 'zigbee2mqtt/CC2591 Extender Garaż': '{"led":false,"linkquality":95}' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper msg_callback(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/binary_sensor.py", line 190, in state_message_received payload = value_template.async_render_with_possible_json_value( File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 274, in async_render_with_possible_json_value self._ensure_compiled() File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 300, in _ensure_compiled assert self.hass is not None, "hass variable not set on template" AssertionError: hass variable not set on template
Exception in state_message_received when handling msg on 'zigbee2mqtt/Xiaomi Door Pokój Mniejszy Uchylenie': '{"battery":100,"contact":true,"linkquality":95,"voltage":3025}' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 35, in wrapper msg_callback(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/binary_sensor.py", line 190, in state_message_received payload = value_template.async_render_with_possible_json_value( File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 274, in async_render_with_possible_json_value self._ensure_compiled() File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 300, in _ensure_compiled assert self.hass is not None, "hass variable not set on template" AssertionError: hass variable not set on template

emontnemery · 2020-09-17T15:16:36Z

OK, very good that it can be reproduced!

However, as mentioned here: #40166 (comment) a full log from HA startup until the issue happens is needed.

Btw, no need to use pastebin, you can zip+attach the log file directly in github, just drag it to the comment field.

andriej · 2020-09-18T07:42:20Z

I hope you've downloaded file.
If not - pls give me an e-mail as there are sensitive details in the log

emontnemery · 2020-09-29T18:46:48Z

@andriej Yes, I downloaded the log. The problem is a race when the MQTT entity config is changed.

dennyreiter · 2020-11-16T02:49:39Z

Did this ever go anywhere? I'm having issues with my Tasmota devices disappearing after upgrading to 0.117.5 or creating multiple entries and the original one I use in automations being dead (for instance, light.credenza_led_strip is dead, but light.credenza_led_strip_2 is working.) I see these in my home-assistant.log:

2020-11-15 20:41:37 ERROR (MainThread) [homeassistant.util.logging] Exception in availability_messag e_received when handling msg on 'tele/credenza/LWT': 'Online' Traceback (most recent call last): File "/home/denny/.pyenv/versions/homeassistant38/lib/python3.8/site-packages/homeassistant/compon ents/mqtt/debug_info.py", line 34, in wrapper _log_message(msg) File "/home/denny/.pyenv/versions/homeassistant38/lib/python3.8/site-packages/homeassistant/compon ents/mqtt/debug_info.py", line 24, in _log_message messages = debug_info["entities"][entity_id]["subscriptions"][ KeyError: 'tele/credenza/LWT'
What other info can I provide to help?

emontnemery · 2020-12-17T18:01:12Z

@dennyreiter I don't think your problem is related to the problem reported by @andriej
Nevertheless, is your problem reproducible?

dennyreiter · 2020-12-17T20:20:23Z

I have not had the problem, but I've switched over to the Tasmota integration since then, along with upgrading the Tasmota devices.

github-actions · 2021-03-17T21:16:42Z

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

andriej · 2021-03-18T06:35:19Z

I'm not sure if it has been fixed

github-actions · 2021-06-16T08:05:45Z

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

pkishino · 2022-01-30T05:23:19Z

I am seeing this issue as well, same error message, different content:

Logger: homeassistant.util.logging
Source: util/logging.py:105
First occurred: 29 January 2022, 11:43:05 (24 occurrences)
Last logged: 29 January 2022, 11:43:05

Exception in availability_message_received when handling msg on 'valetudo/vacuum/$state': 'disconnected' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 36, in wrapper _log_message(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 26, in _log_message messages = debug_info["entities"][entity_id]["subscriptions"][ KeyError: 'sensor.valetudo_vacuum_main_brush'
Exception in availability_message_received when handling msg on 'valetudo/vacuum/$state': 'disconnected' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 36, in wrapper _log_message(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 26, in _log_message messages = debug_info["entities"][entity_id]["subscriptions"][ KeyError: 'sensor.valetudo_vacuum_right_brush'
Exception in availability_message_received when handling msg on 'valetudo/vacuum/$state': 'disconnected' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 36, in wrapper _log_message(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 26, in _log_message messages = debug_info["entities"][entity_id]["subscriptions"][ KeyError: 'sensor.valetudo_vacuum_main_filter'
Exception in availability_message_received when handling msg on 'valetudo/vacuum/$state': 'disconnected' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 36, in wrapper _log_message(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 26, in _log_message messages = debug_info["entities"][entity_id]["subscriptions"][ KeyError: 'sensor.valetudo_vacuum_sensor_cleaning'
Exception in availability_message_received when handling msg on 'valetudo/vacuum/$state': 'disconnected' Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 36, in wrapper _log_message(msg) File "/usr/src/homeassistant/homeassistant/components/mqtt/debug_info.py", line 26, in _log_message messages = debug_info["entities"][entity_id]["subscriptions"][ KeyError: 'camera.valetudo_vacuum_map_data'

Using no yaml. direct HA discovery.
this has been going for a few versions now

emontnemery · 2022-01-31T12:59:11Z

@pkishino Please open a new issue for your problem 👍

emontnemery · 2022-02-01T12:21:05Z

The problem reported by @andriej is because of a race when handling a discovery update.

For example, the MQTT availability mixin does this:

    async def availability_discovery_update(self, config: dict):
        """Handle updated discovery message."""
        self._availability_setup_from_config(config)
        await self._availability_subscribe_topics()

If MQTT messages are received after calling self._availability_setup_from_config(config) but before await self._availability_subscribe_topics() has returned, the availability mixin is configured for the new configuration, but still subscribing to the old topics.

There are several variations of this, but the problem is always that we may handle MQTT messages before the entity is fully setup.

emontnemery · 2022-02-02T12:45:34Z

The problem reported by @andriej should be fixed by #65415

The problem reported by @dennyreiter here: #40166 (comment) may be a different issue.

springstan added the integration: mqtt label Sep 17, 2020

probot-home-assistant bot assigned emontnemery Sep 17, 2020

dennyreiter mentioned this issue Nov 13, 2020

After each restart of HA connection to MQTT/zigbee2mqtt is lost and all devices are unavailable Koenkk/zigbee2mqtt#4912

Closed

github-actions bot added the stale label Mar 17, 2021

github-actions bot removed the stale label Mar 18, 2021

github-actions bot added the stale label Jun 16, 2021

github-actions bot closed this as completed Jun 23, 2021

pkishino mentioned this issue Feb 1, 2022

mqtt: Exception in availability_message_received #65362

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

mqtt: Exception in availability_message_received #40166

mqtt: Exception in availability_message_received #40166

andriej commented Sep 17, 2020

probot-home-assistant bot commented Sep 17, 2020

probot-home-assistant bot commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020 •

edited

Loading

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020 •

edited

Loading

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 18, 2020

emontnemery commented Sep 29, 2020

dennyreiter commented Nov 16, 2020

emontnemery commented Dec 17, 2020

dennyreiter commented Dec 17, 2020

github-actions bot commented Mar 17, 2021

andriej commented Mar 18, 2021

github-actions bot commented Jun 16, 2021

pkishino commented Jan 30, 2022

emontnemery commented Jan 31, 2022

emontnemery commented Feb 1, 2022

emontnemery commented Feb 2, 2022

mqtt: Exception in availability_message_received #40166

mqtt: Exception in availability_message_received #40166

Comments

andriej commented Sep 17, 2020

The problem

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

Additional information

probot-home-assistant bot commented Sep 17, 2020

probot-home-assistant bot commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020 • edited Loading

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020 • edited Loading

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 17, 2020

emontnemery commented Sep 17, 2020

andriej commented Sep 18, 2020

emontnemery commented Sep 29, 2020

dennyreiter commented Nov 16, 2020

emontnemery commented Dec 17, 2020

dennyreiter commented Dec 17, 2020

github-actions bot commented Mar 17, 2021

andriej commented Mar 18, 2021

github-actions bot commented Jun 16, 2021

pkishino commented Jan 30, 2022

emontnemery commented Jan 31, 2022

emontnemery commented Feb 1, 2022

emontnemery commented Feb 2, 2022

Problem-relevant `configuration.yaml`

emontnemery commented Sep 17, 2020 •

edited

Loading

emontnemery commented Sep 17, 2020 •

edited

Loading