Use existing monotonic timestamp on mqtt messages for debugging (#116196)

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:

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"]

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]]

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

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

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 := dt_util.utcnow()):
-    with freeze_time(start_dt):
         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)
+
     assert len(debug_info_data["entities"][0]["subscriptions"]) == 1
     assert (
         len(debug_info_data["entities"][0]["subscriptions"][0]["messages"])
@@ -1401,15 +1400,13 @@ 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)
@@ -1428,9 +1425,10 @@ async def help_test_entity_debug_info_message(
             } in debug_info_data["entities"][0]["subscriptions"]
 
     expected_transmissions = []
+
+    with freeze_time(start_dt := dt_util.utcnow()):
         if service:
             # Trigger an outgoing MQTT message
-        with freeze_time(start_dt):
             if service:
                 service_data = {ATTR_ENTITY_ID: f"{domain}.beer_test"}
                 if service_parameters: