From 877eb0c3add022effa80996425ff74d03fc5e8e0 Mon Sep 17 00:00:00 2001 From: Erik Montnemery Date: Wed, 22 Apr 2020 01:48:04 +0200 Subject: [PATCH] Don't log same MQTT message multiple times (#34511) --- homeassistant/components/mqtt/__init__.py | 14 ++++- homeassistant/components/mqtt/debug_info.py | 6 ++- homeassistant/components/mqtt/models.py | 2 + tests/components/mqtt/test_common.py | 18 +++++-- tests/components/mqtt/test_init.py | 58 +++++++++++++++++++-- 5 files changed, 86 insertions(+), 12 deletions(-) diff --git a/homeassistant/components/mqtt/__init__.py b/homeassistant/components/mqtt/__init__.py index ff99cf59c0b..5c0f3108960 100644 --- a/homeassistant/components/mqtt/__init__.py +++ b/homeassistant/components/mqtt/__init__.py @@ -40,6 +40,7 @@ from homeassistant.helpers.dispatcher import async_dispatcher_connect from homeassistant.helpers.entity import Entity from homeassistant.helpers.typing import ConfigType, HomeAssistantType, ServiceDataType from homeassistant.loader import bind_hass +from homeassistant.util import dt as dt_util from homeassistant.util.async_ import run_callback_threadsafe from homeassistant.util.logging import catch_log_exception @@ -945,7 +946,8 @@ class MQTT: self.async_publish( # pylint: disable=no-value-for-parameter *attr.astuple( self.birth_message, - filter=lambda attr, value: attr.name != "subscribed_topic", + filter=lambda attr, value: attr.name + not in ["subscribed_topic", "timestamp"], ) ) ) @@ -962,6 +964,7 @@ class MQTT: " (retained)" if msg.retain else "", msg.payload, ) + timestamp = dt_util.utcnow() for subscription in self.subscriptions: if not _match_topic(subscription.topic, msg.topic): @@ -983,7 +986,14 @@ class MQTT: self.hass.async_run_job( subscription.callback, - Message(msg.topic, payload, msg.qos, msg.retain, subscription.topic), + Message( + msg.topic, + payload, + msg.qos, + msg.retain, + subscription.topic, + timestamp, + ), ) def _mqtt_on_disconnect(self, _mqttc, _userdata, result_code: int) -> None: diff --git a/homeassistant/components/mqtt/debug_info.py b/homeassistant/components/mqtt/debug_info.py index 796453ec9e7..2a216366bb1 100644 --- a/homeassistant/components/mqtt/debug_info.py +++ b/homeassistant/components/mqtt/debug_info.py @@ -24,7 +24,8 @@ def log_messages(hass: HomeAssistantType, entity_id: str) -> MessageCallbackType messages = debug_info["entities"][entity_id]["subscriptions"][ msg.subscribed_topic ] - messages.append((msg.payload, msg.topic)) + if msg not in messages: + messages.append(msg) def _decorator(msg_callback: MessageCallbackType): @wraps(msg_callback) @@ -125,7 +126,8 @@ async def info_for_device(hass, device_id): { "topic": topic, "messages": [ - {"payload": msg[0], "topic": msg[1]} for msg in list(messages) + {"payload": msg.payload, "time": msg.timestamp, "topic": msg.topic} + for msg in list(messages) ], } for topic, messages in entity_info["subscriptions"].items() diff --git a/homeassistant/components/mqtt/models.py b/homeassistant/components/mqtt/models.py index 3a4add57298..1fb6cd28fac 100644 --- a/homeassistant/components/mqtt/models.py +++ b/homeassistant/components/mqtt/models.py @@ -1,4 +1,5 @@ """Modesl used by multiple MQTT modules.""" +import datetime as dt from typing import Callable, Union import attr @@ -15,6 +16,7 @@ class Message: qos = attr.ib(type=int) retain = attr.ib(type=bool) subscribed_topic = attr.ib(type=str, default=None) + timestamp = attr.ib(type=dt.datetime, default=None) MessageCallbackType = Callable[[Message], None] diff --git a/tests/components/mqtt/test_common.py b/tests/components/mqtt/test_common.py index 3e95e5a1afe..1199aaa40c7 100644 --- a/tests/components/mqtt/test_common.py +++ b/tests/components/mqtt/test_common.py @@ -1,6 +1,8 @@ """Common test objects.""" import copy +from datetime import datetime import json +from unittest import mock from unittest.mock import ANY from homeassistant.components import mqtt @@ -586,8 +588,11 @@ async def help_test_entity_debug_info_max_messages(hass, mqtt_mock, domain, conf "subscriptions" ] - for i in range(0, debug_info.STORED_MESSAGES + 1): - async_fire_mqtt_message(hass, "test-topic", f"{i}") + start_dt = datetime(2019, 1, 1, 0, 0, 0) + with mock.patch("homeassistant.util.dt.utcnow") as dt_utcnow: + dt_utcnow.return_value = start_dt + for i in range(0, debug_info.STORED_MESSAGES + 1): + async_fire_mqtt_message(hass, "test-topic", f"{i}") debug_info_data = await debug_info.info_for_device(hass, device.id) assert len(debug_info_data["entities"][0]["subscriptions"]) == 1 @@ -596,7 +601,7 @@ async def help_test_entity_debug_info_max_messages(hass, mqtt_mock, domain, conf == debug_info.STORED_MESSAGES ) messages = [ - {"topic": "test-topic", "payload": f"{i}"} + {"topic": "test-topic", "payload": f"{i}", "time": start_dt} for i in range(1, debug_info.STORED_MESSAGES + 1) ] assert {"topic": "test-topic", "messages": messages} in debug_info_data["entities"][ @@ -642,13 +647,16 @@ async def help_test_entity_debug_info_message( "subscriptions" ] - async_fire_mqtt_message(hass, topic, payload) + start_dt = datetime(2019, 1, 1, 0, 0, 0) + with mock.patch("homeassistant.util.dt.utcnow") as dt_utcnow: + dt_utcnow.return_value = start_dt + async_fire_mqtt_message(hass, topic, payload) debug_info_data = await debug_info.info_for_device(hass, device.id) assert len(debug_info_data["entities"][0]["subscriptions"]) >= 1 assert { "topic": topic, - "messages": [{"topic": topic, "payload": payload}], + "messages": [{"topic": topic, "payload": payload, "time": start_dt}], } in debug_info_data["entities"][0]["subscriptions"] diff --git a/tests/components/mqtt/test_init.py b/tests/components/mqtt/test_init.py index e70a53caf9d..9b5f70a95ec 100644 --- a/tests/components/mqtt/test_init.py +++ b/tests/components/mqtt/test_init.py @@ -1,5 +1,5 @@ """The tests for the MQTT component.""" -from datetime import timedelta +from datetime import datetime, timedelta import json import ssl import unittest @@ -1266,11 +1266,63 @@ async def test_debug_info_wildcard(hass, mqtt_mock): "subscriptions" ] - async_fire_mqtt_message(hass, "sensor/abc", "123") + start_dt = datetime(2019, 1, 1, 0, 0, 0) + with mock.patch("homeassistant.util.dt.utcnow") as dt_utcnow: + dt_utcnow.return_value = start_dt + async_fire_mqtt_message(hass, "sensor/abc", "123") debug_info_data = await debug_info.info_for_device(hass, device.id) assert len(debug_info_data["entities"][0]["subscriptions"]) >= 1 assert { "topic": "sensor/#", - "messages": [{"topic": "sensor/abc", "payload": "123"}], + "messages": [{"topic": "sensor/abc", "payload": "123", "time": start_dt}], } in debug_info_data["entities"][0]["subscriptions"] + + +async def test_debug_info_filter_same(hass, mqtt_mock): + """Test debug info removes messages with same timestamp.""" + config = { + "device": {"identifiers": ["helloworld"]}, + "platform": "mqtt", + "name": "test", + "state_topic": "sensor/#", + "unique_id": "veryunique", + } + + entry = MockConfigEntry(domain=mqtt.DOMAIN) + entry.add_to_hass(hass) + await async_start(hass, "homeassistant", {}, entry) + registry = await hass.helpers.device_registry.async_get_registry() + + data = json.dumps(config) + async_fire_mqtt_message(hass, "homeassistant/sensor/bla/config", data) + await hass.async_block_till_done() + + device = registry.async_get_device({("mqtt", "helloworld")}, set()) + assert device is not None + + debug_info_data = await debug_info.info_for_device(hass, device.id) + assert len(debug_info_data["entities"][0]["subscriptions"]) >= 1 + assert {"topic": "sensor/#", "messages": []} in debug_info_data["entities"][0][ + "subscriptions" + ] + + dt1 = datetime(2019, 1, 1, 0, 0, 0) + dt2 = datetime(2019, 1, 1, 0, 0, 1) + with mock.patch("homeassistant.util.dt.utcnow") as dt_utcnow: + dt_utcnow.return_value = dt1 + async_fire_mqtt_message(hass, "sensor/abc", "123") + async_fire_mqtt_message(hass, "sensor/abc", "123") + dt_utcnow.return_value = dt2 + async_fire_mqtt_message(hass, "sensor/abc", "123") + + debug_info_data = await debug_info.info_for_device(hass, device.id) + assert len(debug_info_data["entities"][0]["subscriptions"]) == 1 + assert len(debug_info_data["entities"][0]["subscriptions"][0]["messages"]) == 2 + assert { + "topic": "sensor/#", + "messages": [ + {"topic": "sensor/abc", "payload": "123", "time": dt1}, + {"topic": "sensor/abc", "payload": "123", "time": dt2}, + ], + } == debug_info_data["entities"][0]["subscriptions"][0]