Add event statistics to Sonos diagnostics (#64845)

homeassistant/components/sonos/__init__.py

@@ -192,6 +192,8 @@ class SonosDiscoveryManager:
         return None
 
     async def _async_stop_event_listener(self, event: Event | None = None) -> None:
+        for speaker in self.data.discovered.values():
+            speaker.event_stats.log_report()
         await asyncio.gather(
             *(speaker.async_offline() for speaker in self.data.discovered.values())
         )

homeassistant/components/sonos/alarms.py

@@ -3,18 +3,21 @@ from __future__ import annotations
 
 from collections.abc import Iterator
 import logging
-from typing import Any
+from typing import TYPE_CHECKING, Any
 
 from soco import SoCo
 from soco.alarms import Alarm, Alarms
+from soco.events_base import Event as SonosEvent
 from soco.exceptions import SoCoException
 
-from homeassistant.core import callback
 from homeassistant.helpers.dispatcher import async_dispatcher_send
 
 from .const import DATA_SONOS, SONOS_ALARMS_UPDATED, SONOS_CREATE_ALARM
 from .household_coordinator import SonosHouseholdCoordinator
 
+if TYPE_CHECKING:
+    from .speaker import SonosSpeaker
+
 _LOGGER = logging.getLogger(__name__)
 
 
@@ -55,20 +58,18 @@ class SonosAlarms(SonosHouseholdCoordinator):
                 )
         async_dispatcher_send(self.hass, f"{SONOS_ALARMS_UPDATED}-{self.household_id}")
 
-    @callback
-    def async_handle_event(self, event_id: str, soco: SoCo) -> None:
-        """Create a task to update from an event callback."""
-        _, event_id = event_id.split(":")
-        event_id = int(event_id)
-        self.hass.async_create_task(self.async_process_event(event_id, soco))
-
-    async def async_process_event(self, event_id: str, soco: SoCo) -> None:
+    async def async_process_event(
+        self, event: SonosEvent, speaker: SonosSpeaker
+    ) -> None:
         """Process the event payload in an async lock and update entities."""
+        event_id = event.variables["alarm_list_version"].split(":")[-1]
+        event_id = int(event_id)
         async with self.cache_update_lock:
             if event_id <= self.last_processed_event_id:
                 # Skip updates if this event_id has already been seen
                 return
-            await self.async_update_entities(soco, event_id)
+            speaker.event_stats.process(event)
+            await self.async_update_entities(speaker.soco, event_id)
 
     def update_cache(self, soco: SoCo, update_id: int | None = None) -> bool:
         """Update cache of known alarms and return if cache has changed."""

homeassistant/components/sonos/diagnostics.py

@@ -112,4 +112,5 @@ async def async_generate_speaker_info(
         if s is speaker
     }
     payload["media"] = await async_generate_media_info(hass, speaker)
+    payload["event_stats"] = speaker.event_stats.report()
     return payload

homeassistant/components/sonos/favorites.py

@@ -4,18 +4,21 @@ from __future__ import annotations
 from collections.abc import Iterator
 import logging
 import re
-from typing import Any
+from typing import TYPE_CHECKING, Any
 
 from soco import SoCo
 from soco.data_structures import DidlFavorite
+from soco.events_base import Event as SonosEvent
 from soco.exceptions import SoCoException
 
-from homeassistant.core import callback
 from homeassistant.helpers.dispatcher import async_dispatcher_send
 
 from .const import SONOS_FAVORITES_UPDATED
 from .household_coordinator import SonosHouseholdCoordinator
 
+if TYPE_CHECKING:
+    from .speaker import SonosSpeaker
+
 _LOGGER = logging.getLogger(__name__)
 
 
@@ -51,45 +54,41 @@ class SonosFavorites(SonosHouseholdCoordinator):
             self.hass, f"{SONOS_FAVORITES_UPDATED}-{self.household_id}"
         )
 
-    @callback
-    def async_handle_event(self, event_id: str, container_ids: str, soco: SoCo) -> None:
-        """Create a task to update from an event callback."""
+    async def async_process_event(
+        self, event: SonosEvent, speaker: SonosSpeaker
+    ) -> None:
+        """Process the event payload in an async lock and update entities."""
+        event_id = event.variables["favorites_update_id"]
+        container_ids = event.variables["container_update_i_ds"]
         if not (match := re.search(r"FV:2,(\d+)", container_ids)):
             return
 
         container_id = int(match.groups()[0])
         event_id = int(event_id.split(",")[-1])
 
-        self.hass.async_create_task(
-            self.async_process_event(event_id, container_id, soco)
-        )
-
-    async def async_process_event(
-        self, event_id: int, container_id: int, soco: SoCo
-    ) -> None:
-        """Process the event payload in an async lock and update entities."""
         async with self.cache_update_lock:
-            last_poll_id = self.last_polled_ids.get(soco.uid)
+            last_poll_id = self.last_polled_ids.get(speaker.uid)
             if (
                 self.last_processed_event_id
                 and event_id <= self.last_processed_event_id
             ):
                 # Skip updates if this event_id has already been seen
                 if not last_poll_id:
-                    self.last_polled_ids[soco.uid] = container_id
+                    self.last_polled_ids[speaker.uid] = container_id
                 return
 
             if last_poll_id and container_id <= last_poll_id:
                 return
 
+            speaker.event_stats.process(event)
             _LOGGER.debug(
                 "New favorites event %s from %s (was %s)",
                 event_id,
-                soco,
+                speaker.soco,
                 self.last_processed_event_id,
             )
             self.last_processed_event_id = event_id
-            await self.async_update_entities(soco, container_id)
+            await self.async_update_entities(speaker.soco, container_id)
 
     def update_cache(self, soco: SoCo, update_id: int | None = None) -> bool:
         """Update cache of known favorites and return if cache has changed."""

homeassistant/components/sonos/speaker.py

@@ -61,6 +61,7 @@ from .const import (
 )
 from .favorites import SonosFavorites
 from .helpers import soco_error
+from .statistics import EventStatistics
 
 NEVER_TIME = -1200.0
 EVENT_CHARGING = {
@@ -157,20 +158,6 @@ class SonosSpeaker:
         self._share_link_plugin: ShareLinkPlugin | None = None
         self.available = True
 
-        # Subscriptions and events
-        self.subscriptions_failed: bool = False
-        self._subscriptions: list[SubscriptionBase] = []
-        self._resubscription_lock: asyncio.Lock | None = None
-        self._event_dispatchers: dict[str, Callable] = {}
-        self._last_activity: float = NEVER_TIME
-        self._last_event_cache: dict[str, Any] = {}
-
-        # Scheduled callback handles
-        self._poll_timer: Callable | None = None
-
-        # Dispatcher handles
-        self.dispatchers: list[Callable] = []
-
         # Device information
         self.hardware_version = speaker_info["hardware_version"]
         self.software_version = speaker_info["software_version"]
@@ -181,6 +168,21 @@ class SonosSpeaker:
         self.version = speaker_info["display_version"]
         self.zone_name = speaker_info["zone_name"]
 
+        # Subscriptions and events
+        self.subscriptions_failed: bool = False
+        self._subscriptions: list[SubscriptionBase] = []
+        self._resubscription_lock: asyncio.Lock | None = None
+        self._event_dispatchers: dict[str, Callable] = {}
+        self._last_activity: float = NEVER_TIME
+        self._last_event_cache: dict[str, Any] = {}
+        self.event_stats: EventStatistics = EventStatistics(self.zone_name)
+
+        # Scheduled callback handles
+        self._poll_timer: Callable | None = None
+
+        # Dispatcher handles
+        self.dispatchers: list[Callable] = []
+
         # Battery
         self.battery_info: dict[str, Any] = {}
         self._last_battery_event: datetime.datetime | None = None
@@ -426,10 +428,12 @@ class SonosSpeaker:
             self._poll_timer = None
 
         self.speaker_activity(f"{event.service.service_type} subscription")
+        self.event_stats.receive(event)
 
         # Skip if this update is an unchanged subset of the previous event
         if last_event := self._last_event_cache.get(event.service.service_type):
             if event.variables.items() <= last_event.items():
+                self.event_stats.duplicate(event)
                 return
 
         # Save most recently processed event variables for cache and diagnostics
@@ -440,13 +444,14 @@ class SonosSpeaker:
     @callback
     def async_dispatch_alarms(self, event: SonosEvent) -> None:
         """Add the soco instance associated with the event to the callback."""
-        if not (event_id := event.variables.get("alarm_list_version")):
+        if "alarm_list_version" not in event.variables:
             return
-        self.alarms.async_handle_event(event_id, self.soco)
+        self.hass.async_create_task(self.alarms.async_process_event(event, self))
 
     @callback
     def async_dispatch_device_properties(self, event: SonosEvent) -> None:
         """Update device properties from an event."""
+        self.event_stats.process(event)
         self.hass.async_create_task(self.async_update_device_properties(event))
 
     async def async_update_device_properties(self, event: SonosEvent) -> None:
@@ -465,11 +470,11 @@ class SonosSpeaker:
     @callback
     def async_dispatch_favorites(self, event: SonosEvent) -> None:
         """Add the soco instance associated with the event to the callback."""
-        if not (event_id := event.variables.get("favorites_update_id")):
+        if "favorites_update_id" not in event.variables:
             return
-        if not (container_ids := event.variables.get("container_update_i_ds")):
+        if "container_update_i_ds" not in event.variables:
             return
-        self.favorites.async_handle_event(event_id, container_ids, self.soco)
+        self.hass.async_create_task(self.favorites.async_process_event(event, self))
 
     @callback
     def async_dispatch_media_update(self, event: SonosEvent) -> None:
@@ -482,6 +487,7 @@ class SonosSpeaker:
     @callback
     def async_update_volume(self, event: SonosEvent) -> None:
         """Update information about currently volume settings."""
+        self.event_stats.process(event)
         variables = event.variables
 
         if "volume" in variables:
@@ -670,6 +676,7 @@ class SonosSpeaker:
         """Handle callback for topology change event."""
         if not hasattr(event, "zone_player_uui_ds_in_group"):
             return
+        self.event_stats.process(event)
         self.hass.async_create_task(self.create_update_groups_coro(event))
 
     def create_update_groups_coro(self, event: SonosEvent | None = None) -> Coroutine:
@@ -1013,6 +1020,9 @@ class SonosSpeaker:
         if new_status == SONOS_STATE_TRANSITIONING:
             return
 
+        if event:
+            self.event_stats.process(event)
+
         self.media.clear()
         update_position = new_status != self.media.playback_status
         self.media.playback_status = new_status

homeassistant/components/sonos/statistics.py

@@ -0,0 +1,48 @@
+"""Class to track subscription event statistics."""
+from __future__ import annotations
+
+import logging
+
+from soco.data_structures_entry import from_didl_string
+from soco.events_base import Event as SonosEvent, parse_event_xml
+
+_LOGGER = logging.getLogger(__name__)
+
+
+class EventStatistics:
+    """Representation of Sonos event statistics."""
+
+    def __init__(self, zone_name: str) -> None:
+        """Initialize EventStatistics."""
+        self._stats = {}
+        self.zone_name = zone_name
+
+    def receive(self, event: SonosEvent) -> None:
+        """Mark a received event by subscription type."""
+        stats_entry = self._stats.setdefault(
+            event.service.service_type, {"received": 0, "duplicates": 0, "processed": 0}
+        )
+        stats_entry["received"] += 1
+
+    def duplicate(self, event: SonosEvent) -> None:
+        """Mark a duplicate event by subscription type."""
+        self._stats[event.service.service_type]["duplicates"] += 1
+
+    def process(self, event: SonosEvent) -> None:
+        """Mark a fully processed event by subscription type."""
+        self._stats[event.service.service_type]["processed"] += 1
+
+    def report(self) -> dict:
+        """Generate a report for use in diagnostics."""
+        payload = self._stats.copy()
+        payload["soco:from_didl_string"] = from_didl_string.cache_info()
+        payload["soco:parse_event_xml"] = parse_event_xml.cache_info()
+        return payload
+
+    def log_report(self) -> None:
+        """Log event statistics for this speaker."""
+        _LOGGER.debug(
+            "Event statistics for %s: %s",
+            self.zone_name,
+            self.report(),
+        )

tests/components/sonos/test_statistics.py

@@ -0,0 +1,30 @@
+"""Tests for the Sonos statistics."""
+from homeassistant.components.sonos.const import DATA_SONOS
+
+
+async def test_statistics_duplicate(
+    hass, async_autosetup_sonos, soco, device_properties_event
+):
+    """Test Sonos statistics."""
+    speaker = list(hass.data[DATA_SONOS].discovered.values())[0]
+
+    subscription = soco.deviceProperties.subscribe.return_value
+    sub_callback = subscription.callback
+
+    # Update the speaker with a callback event
+    sub_callback(device_properties_event)
+    await hass.async_block_till_done()
+
+    report = speaker.event_stats.report()
+    assert report["DeviceProperties"]["received"] == 1
+    assert report["DeviceProperties"]["duplicates"] == 0
+    assert report["DeviceProperties"]["processed"] == 1
+
+    # Ensure a duplicate is registered in the statistics
+    sub_callback(device_properties_event)
+    await hass.async_block_till_done()
+
+    report = speaker.event_stats.report()
+    assert report["DeviceProperties"]["received"] == 2
+    assert report["DeviceProperties"]["duplicates"] == 1
+    assert report["DeviceProperties"]["processed"] == 1