diff --git a/homeassistant/components/sonos/__init__.py b/homeassistant/components/sonos/__init__.py index b4be0966ada..27b9d720b0f 100644 --- a/homeassistant/components/sonos/__init__.py +++ b/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()) ) diff --git a/homeassistant/components/sonos/alarms.py b/homeassistant/components/sonos/alarms.py index 73149c6a286..dfe9e8328a4 100644 --- a/homeassistant/components/sonos/alarms.py +++ b/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.""" diff --git a/homeassistant/components/sonos/diagnostics.py b/homeassistant/components/sonos/diagnostics.py index 2b0d280b437..3f1806d0877 100644 --- a/homeassistant/components/sonos/diagnostics.py +++ b/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 diff --git a/homeassistant/components/sonos/favorites.py b/homeassistant/components/sonos/favorites.py index 2b362014ecf..64c5b743809 100644 --- a/homeassistant/components/sonos/favorites.py +++ b/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.""" diff --git a/homeassistant/components/sonos/speaker.py b/homeassistant/components/sonos/speaker.py index 1993ab418c5..2f1030fdca8 100644 --- a/homeassistant/components/sonos/speaker.py +++ b/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 diff --git a/homeassistant/components/sonos/statistics.py b/homeassistant/components/sonos/statistics.py new file mode 100644 index 00000000000..8cade9b0aa5 --- /dev/null +++ b/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(), + ) diff --git a/tests/components/sonos/test_statistics.py b/tests/components/sonos/test_statistics.py new file mode 100644 index 00000000000..4270a13e65c --- /dev/null +++ b/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