mqtt: Exception in availability_message_received

andriej commented 4 years ago

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. https://github.com/home-assistant/core/issues/39860

probot-home-assistant[bot] commented 4 years ago

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

probot-home-assistant[bot] commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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: https://github.com/Koenkk/zigbee2mqtt/issues/775#issuecomment-658954308

andriej commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

Yes, I did.

emontnemery commented 4 years ago

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

andriej commented 4 years ago

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

emontnemery commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

OK, very good that it can be reproduced!

However, as mentioned here: https://github.com/home-assistant/core/issues/40166#issuecomment-694164219 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 commented 4 years ago

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

emontnemery commented 4 years ago

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

dennyreiter commented 4 years ago

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 commented 3 years ago

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

dennyreiter commented 3 years ago

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[bot] commented 3 years ago

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 commented 3 years ago

I'm not sure if it has been fixed

github-actions[bot] commented 3 years ago

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 commented 2 years ago

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 commented 2 years ago

@pkishino Please open a new issue for your problem 👍

emontnemery commented 2 years ago

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 commented 2 years ago

The problem reported by @andriej should be fixed by https://github.com/home-assistant/core/pull/65415

The problem reported by @dennyreiter here: https://github.com/home-assistant/core/issues/40166#issuecomment-727701492 may be a different issue.

home-assistant / core