From 372c6c7874c15d29522587428e35b2586d866ada Mon Sep 17 00:00:00 2001 From: Jan Bouwhuis Date: Fri, 26 Apr 2024 02:09:54 +0200 Subject: [PATCH] Use existing monotonic timestamp on mqtt messages for debugging (#116196) --- homeassistant/components/mqtt/client.py | 5 +- homeassistant/components/mqtt/debug_info.py | 16 +++-- homeassistant/components/mqtt/models.py | 3 +- homeassistant/helpers/service_info/mqtt.py | 3 +- tests/common.py | 1 + tests/components/mqtt/test_common.py | 78 ++++++++++----------- 6 files changed, 54 insertions(+), 52 deletions(-) diff --git a/homeassistant/components/mqtt/client.py b/homeassistant/components/mqtt/client.py index 133991ade16..f01b8e80b3d 100644 --- a/homeassistant/components/mqtt/client.py +++ b/homeassistant/components/mqtt/client.py @@ -40,7 +40,6 @@ from homeassistant.exceptions import HomeAssistantError from homeassistant.helpers.dispatcher import async_dispatcher_send from homeassistant.helpers.typing import ConfigType from homeassistant.loader import bind_hass -from homeassistant.util import dt as dt_util from homeassistant.util.async_ import create_eager_task from homeassistant.util.logging import catch_log_exception @@ -991,8 +990,6 @@ class MQTT: msg.qos, msg.payload[0:8192], ) - timestamp = dt_util.utcnow() - subscriptions = self._matching_subscriptions(topic) msg_cache_by_subscription_topic: dict[str, ReceiveMessage] = {} @@ -1030,7 +1027,7 @@ class MQTT: msg.qos, msg.retain, subscription_topic, - timestamp, + msg.timestamp, ) msg_cache_by_subscription_topic[subscription_topic] = receive_msg else: diff --git a/homeassistant/components/mqtt/debug_info.py b/homeassistant/components/mqtt/debug_info.py index 7ff93a6bd06..e84dedde785 100644 --- a/homeassistant/components/mqtt/debug_info.py +++ b/homeassistant/components/mqtt/debug_info.py @@ -7,6 +7,7 @@ from collections.abc import Callable from dataclasses import dataclass import datetime as dt from functools import wraps +import time from typing import TYPE_CHECKING, Any from homeassistant.core import HomeAssistant @@ -57,7 +58,7 @@ class TimestampedPublishMessage: payload: PublishPayloadType qos: int retain: bool - timestamp: dt.datetime + timestamp: float def log_message( @@ -77,7 +78,7 @@ def log_message( "messages": deque([], STORED_MESSAGES), } msg = TimestampedPublishMessage( - topic, payload, qos, retain, timestamp=dt_util.utcnow() + topic, payload, qos, retain, timestamp=time.monotonic() ) entity_info["transmitted"][topic]["messages"].append(msg) @@ -175,6 +176,7 @@ def remove_trigger_discovery_data( def _info_for_entity(hass: HomeAssistant, entity_id: str) -> dict[str, Any]: entity_info = get_mqtt_data(hass).debug_info_entities[entity_id] + monotonic_time_diff = time.time() - time.monotonic() subscriptions = [ { "topic": topic, @@ -183,7 +185,10 @@ def _info_for_entity(hass: HomeAssistant, entity_id: str) -> dict[str, Any]: "payload": str(msg.payload), "qos": msg.qos, "retain": msg.retain, - "time": msg.timestamp, + "time": dt_util.utc_from_timestamp( + msg.timestamp + monotonic_time_diff, + tz=dt.UTC, + ), "topic": msg.topic, } for msg in subscription["messages"] @@ -199,7 +204,10 @@ def _info_for_entity(hass: HomeAssistant, entity_id: str) -> dict[str, Any]: "payload": str(msg.payload), "qos": msg.qos, "retain": msg.retain, - "time": msg.timestamp, + "time": dt_util.utc_from_timestamp( + msg.timestamp + monotonic_time_diff, + tz=dt.UTC, + ), "topic": msg.topic, } for msg in subscription["messages"] diff --git a/homeassistant/components/mqtt/models.py b/homeassistant/components/mqtt/models.py index f53643268e7..17640c3e733 100644 --- a/homeassistant/components/mqtt/models.py +++ b/homeassistant/components/mqtt/models.py @@ -7,7 +7,6 @@ import asyncio from collections import deque from collections.abc import Callable, Coroutine from dataclasses import dataclass, field -import datetime as dt from enum import StrEnum import logging from typing import TYPE_CHECKING, Any, TypedDict @@ -67,7 +66,7 @@ class ReceiveMessage: qos: int retain: bool subscribed_topic: str - timestamp: dt.datetime + timestamp: float AsyncMessageCallbackType = Callable[[ReceiveMessage], Coroutine[Any, Any, None]] diff --git a/homeassistant/helpers/service_info/mqtt.py b/homeassistant/helpers/service_info/mqtt.py index 172a5eeff33..b683745e1c0 100644 --- a/homeassistant/helpers/service_info/mqtt.py +++ b/homeassistant/helpers/service_info/mqtt.py @@ -1,7 +1,6 @@ """MQTT Discovery data.""" from dataclasses import dataclass -import datetime as dt from homeassistant.data_entry_flow import BaseServiceInfo @@ -17,4 +16,4 @@ class MqttServiceInfo(BaseServiceInfo): qos: int retain: bool subscribed_topic: str - timestamp: dt.datetime + timestamp: float diff --git a/tests/common.py b/tests/common.py index b5fe0f7bae1..7bb16ce5c54 100644 --- a/tests/common.py +++ b/tests/common.py @@ -449,6 +449,7 @@ def async_fire_mqtt_message( msg.payload = payload msg.qos = qos msg.retain = retain + msg.timestamp = time.monotonic() mqtt_data: MqttData = hass.data["mqtt"] assert mqtt_data.client diff --git a/tests/components/mqtt/test_common.py b/tests/components/mqtt/test_common.py index e9c3b57777f..ba767f51ac6 100644 --- a/tests/components/mqtt/test_common.py +++ b/tests/components/mqtt/test_common.py @@ -3,7 +3,6 @@ from collections.abc import Iterable from contextlib import suppress import copy -from datetime import datetime import json from pathlib import Path from typing import Any @@ -1326,12 +1325,12 @@ async def help_test_entity_debug_info_max_messages( "subscriptions" ] - start_dt = datetime(2019, 1, 1, 0, 0, 0, tzinfo=dt_util.UTC) - with freeze_time(start_dt): + with freeze_time(start_dt := dt_util.utcnow()): for i in range(debug_info.STORED_MESSAGES + 1): async_fire_mqtt_message(hass, "test-topic", f"{i}") - debug_info_data = debug_info.info_for_device(hass, device.id) + debug_info_data = 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"]) @@ -1401,36 +1400,35 @@ async def help_test_entity_debug_info_message( debug_info_data = debug_info.info_for_device(hass, device.id) - start_dt = datetime(2019, 1, 1, 0, 0, 0, tzinfo=dt_util.UTC) - if state_topic is not None: assert len(debug_info_data["entities"][0]["subscriptions"]) >= 1 assert {"topic": state_topic, "messages": []} in debug_info_data["entities"][0][ "subscriptions" ] - with freeze_time(start_dt): + with freeze_time(start_dt := dt_util.utcnow()): async_fire_mqtt_message(hass, str(state_topic), state_payload) - debug_info_data = debug_info.info_for_device(hass, device.id) - assert len(debug_info_data["entities"][0]["subscriptions"]) >= 1 - assert { - "topic": state_topic, - "messages": [ - { - "payload": str(state_payload), - "qos": 0, - "retain": False, - "time": start_dt, - "topic": state_topic, - } - ], - } in debug_info_data["entities"][0]["subscriptions"] + debug_info_data = debug_info.info_for_device(hass, device.id) + assert len(debug_info_data["entities"][0]["subscriptions"]) >= 1 + assert { + "topic": state_topic, + "messages": [ + { + "payload": str(state_payload), + "qos": 0, + "retain": False, + "time": start_dt, + "topic": state_topic, + } + ], + } in debug_info_data["entities"][0]["subscriptions"] expected_transmissions = [] - if service: - # Trigger an outgoing MQTT message - with freeze_time(start_dt): + + with freeze_time(start_dt := dt_util.utcnow()): + if service: + # Trigger an outgoing MQTT message if service: service_data = {ATTR_ENTITY_ID: f"{domain}.beer_test"} if service_parameters: @@ -1443,23 +1441,23 @@ async def help_test_entity_debug_info_message( blocking=True, ) - expected_transmissions = [ - { - "topic": command_topic, - "messages": [ - { - "payload": str(command_payload), - "qos": 0, - "retain": False, - "time": start_dt, - "topic": command_topic, - } - ], - } - ] + expected_transmissions = [ + { + "topic": command_topic, + "messages": [ + { + "payload": str(command_payload), + "qos": 0, + "retain": False, + "time": start_dt, + "topic": command_topic, + } + ], + } + ] - debug_info_data = debug_info.info_for_device(hass, device.id) - assert debug_info_data["entities"][0]["transmitted"] == expected_transmissions + debug_info_data = debug_info.info_for_device(hass, device.id) + assert debug_info_data["entities"][0]["transmitted"] == expected_transmissions async def help_test_entity_debug_info_remove(