diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml new file mode 100644 index 0000000..fedab99 --- /dev/null +++ b/.github/workflows/tests.yml @@ -0,0 +1,39 @@ +name: Unit Tests + +on: + pull_request: + branches: + - main + - dev + push: + branches: + - main + - dev + +jobs: + test: + runs-on: ubuntu-latest + container: + image: python:3.8 + + steps: + - name: Checkout code + uses: actions/checkout@v4 + + - name: Install dependencies + run: | + pip install --upgrade pip + pip install soco==0.24.0 + pip install git+https://github.com/majamassarini/automate-home.git + + - name: Run unit tests + run: | + python -m unittest discover -v + + - name: Run doctests + run: | + python -m doctest soco_plugin/gateway.py -v + python -m doctest soco_plugin/message.py -v + python -m doctest soco_plugin/command/play.py -v + python -m doctest soco_plugin/command/pause.py -v + python -m doctest soco_plugin/command/stop.py -v diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..3bbe7b6 --- /dev/null +++ b/.gitignore @@ -0,0 +1,3 @@ +__pycache__/ +*.pyc +*.pyo diff --git a/README.md b/README.md index 53ec3a3..4ae288f 100644 --- a/README.md +++ b/README.md @@ -123,6 +123,69 @@ Trigger and command for a [sound player model](https://automate-home.readthedocs - !home.appliance.sound.player.event.forced.Event.Not ``` +## Known Issues: Command Echo Problem + +### Problem Description + +The SoCo library (underlying Sonos communication library) does **not** distinguish between: +- Events triggered by commands sent from automate-home +- Events triggered by user actions (Sonos app, physical speaker controls) + +This creates a "command echo" problem where your own commands trigger state change events. + +### Example Scenario + +When pressing a button to enable Forced Circadian Rhythm mode on a Sonos speaker: + +1. **Button pressed** → sends `forced.Event.CircadianRhythm` → State becomes **Forced Circadian Rhythm** +2. **Performer executes commands** in sequence: + - `mode.Command` (set shuffle mode) + - `playlist.Command` (select playlist) + - `volume.Command` (set volume) + - `play.Command` (start playback) +3. **During reconfiguration**: Sonos internally pauses → fires `pause.Trigger` → sends `forced.Event.Off` → State becomes **Off** (unforced!) +4. **After reconfiguration**: Sonos starts playing → fires `play.Trigger` → sends `forced.Event.On` → State becomes **Forced On** (WRONG! Should be Forced Circadian Rhythm) + +### Why This Happens + +- Sonos speakers send pause events during mode/playlist reconfiguration +- The pause trigger (lines 25-28 in example above) interprets this as user action +- This unforces the state prematurely +- Subsequent play event from Sonos is then interpreted as generic "forced on" instead of maintaining circadian rhythm mode + +### Root Cause + +The SoCo Event objects contain: +- `sid`: subscription ID +- `seq`: event sequence number +- `service`: subscribed service (avTransport or renderingControl) +- `timestamp`: when event was received +- `variables`: state variables like `transport_state` and `volume` + +**They do NOT contain:** +- Command correlation ID +- Source identifier (app vs. external command vs. button) +- Any way to distinguish "echo of your command" from "actual user action" + +This is a fundamental limitation of the Sonos UPnP event system and cannot be fully solved without changes to the SoCo library or Sonos firmware. + +### Current Mitigation: Appliance-level Event Disabling + +The mitigation is implemented at the automate-home appliance state machine level rather +than in this plugin. When a Sonos player enters a playing state (Fade In, Forced On, +Forced Circadian Rhythm), automate-home temporarily disables `forced.Event.Off` in the +appliance state machine so that echo events from Sonos are silently ignored: + +1. **On state entry** — a `state.entering.disable_events.Trigger` immediately calls + `appliance.disable(forced.Event.Off)`. Any `stop`/`pause` echo arriving from Sonos + is ignored by the state machine. +2. **After 30 seconds** — a `state.entering.delay.enable_events.Trigger` calls + `appliance.enable(forced.Event.Off)`. Legitimate stop/pause commands from the user + are processed normally again. + +This plugin passes all Sonos events through without any filtering; the suppression +window is configured entirely in the automate-home scheduler trigger YAML. + ## Documentation * [automate-home protocol commands/triggers chapter](https://automate-home.readthedocs.io/en/latest/performer.html) diff --git a/soco_plugin/gateway.py b/soco_plugin/gateway.py index 45ddd53..a1571e5 100644 --- a/soco_plugin/gateway.py +++ b/soco_plugin/gateway.py @@ -1,4 +1,3 @@ -import time import asyncio import logging import requests @@ -14,37 +13,18 @@ class Gateway(home.protocol.Gateway): PROTOCOL = Description.PROTOCOL - SEND_MESSAGE_TIMEOUT = 1 - POLL_TIMEOUT = 0.05 def __init__(self): self._players = {} self._loop = asyncio.get_event_loop() self.executor = ThreadPoolExecutor(max_workers=100) - - # lock events - # generated by our commands - self._players_locked = {} - self.logger = logging.getLogger(__name__) - self._waiting_for_response = dict() - self._waiting_for_response_type = dict() - async def disconnect(self) -> None: - for (player, sub_rendering, sub_avtransport) in self._players: + for (player, sub_rendering, sub_avtransport) in self._players.values(): player.renderingControl.unsubscribe() player.avTransport.unsubscribe() - - @staticmethod - def find_player(logger, name): - while True: - try: - return soco.discovery.scan_network_get_by_name(name) - except Exception as e: - logger.error(e) - player = None - time.sleep(120) + self.executor.shutdown(wait=True) async def _associate( self, descriptions: Iterable["soco_plugin.Description"] @@ -54,7 +34,7 @@ async def _associate( if name not in self._players: try: player = await self._loop.run_in_executor( - self.executor, lambda: self.find_player(self.logger, name) + self.executor, lambda: soco.discovery.scan_network_get_by_name(name) ) except TypeError as e: self.logger.error(e) @@ -67,11 +47,14 @@ async def _associate( player = None self.logger.info("Player %s: %s" % (name, str(player))) if player: - sub_rendering = player.renderingControl.subscribe() - sub_avtransport = player.avTransport.subscribe() + # Subscribe calls are blocking and must run in executor + sub_rendering = await self._loop.run_in_executor( + self.executor, lambda: player.renderingControl.subscribe() + ) + sub_avtransport = await self._loop.run_in_executor( + self.executor, lambda: player.avTransport.subscribe() + ) self._players[name] = (player, sub_rendering, sub_avtransport) - self._waiting_for_response[player] = False - self._waiting_for_response_type[player] = None async def associate_commands( self, descriptions: Iterable["soco_plugin.Command"] @@ -125,46 +108,19 @@ def build_msgs_from_bus( return msgs async def _wait_for_event(self, player: soco.SoCo, channel, tasks) -> None: - self.logger.info("Waiting for events at player {}".format(player.player_name)) + self.logger.info("Waiting for events from player {}".format(player.player_name)) while True: await asyncio.sleep(0.01) # avoid potential starvation try: event = await self._loop.run_in_executor( self.executor, lambda: channel.events.get(block=True) ) - self.logger.info("Soco event {}".format(event)) + self.logger.debug("Sonos event from %s: %s" % (player.player_name, str(event))) msgs = self.build_msgs_from_bus(player, event) for task in tasks: for msg in msgs: - if self._waiting_for_response[player]: - if self._waiting_for_response_type[player]: - if ( - msg["name"] - == self._waiting_for_response_type[player] - ): - self.logger.debug( - "processed msg {} of waited type".format(msg) - ) - self._loop.create_task(task(msg), name="Soco process msg {}".format(msg)) - else: - self.logger.debug( - "waiting for response type {} received response of type {}".format( - self._waiting_for_response_type[player], - msg["name"], - ) - ) - else: - self.logger.debug( - "waiting for response type {} received response of type {}".format( - self._waiting_for_response_type[player], - msg["name"], - ) - ) - else: - self.logger.debug( - "processed msg {} no waited response".format(msg) - ) - self._loop.create_task(task(msg), name="Soco process msg {}".format(msg)) + self.logger.debug("Processing Sonos event: {}".format(msg)) + self._loop.create_task(task(msg)) except Exception as e: self.logger.error(e) @@ -174,6 +130,7 @@ def get_action(player: soco.SoCo, msg: "soco_plugin.message.Command") -> Callabl >>> import home >>> import soco_plugin >>> class Player: + ... player_name = "TestPlayer" ... def play(self): ... print("play") ... def pause(self): @@ -194,7 +151,12 @@ def get_action(player: soco.SoCo, msg: "soco_plugin.message.Command") -> Callabl ... print("play mode is {}".format(mode)) ... def get_sonos_playlist_by_attr(self, attr, title): ... print ("playlist title is {}".format(title)) - ... return {"uri": "a uri"} + ... class Playlist: + ... def __init__(self): + ... class Resource: + ... uri = "a uri" + ... self.resources = [Resource()] + ... return Playlist() ... def clear_queue(self): ... pass ... def add_uri_to_queue(self, uri): @@ -264,71 +226,42 @@ def get_action(player: soco.SoCo, msg: "soco_plugin.message.Command") -> Callabl async def send_msg( self, msg: "soco_plugin.message.Command", player: soco.SoCo ) -> None: - self.logger.info("send msg {} to player {}".format(msg, player.player_name)) + self.logger.info("Executing Sonos action {} on player {}".format(msg["name"], player.player_name)) if msg: action = self.get_action(player, msg) if action: + self.logger.info("Action found: {}".format(action)) try: await self._loop.run_in_executor(self.executor, action) + self.logger.info("Action executed successfully") except soco.exceptions.SoCoUPnPException as e: - self.logger.error(e) + self.logger.error("SoCo UPnP exception: {}".format(e)) except Exception as e: - self.logger.error(e) - - async def _cancel_waiting_on_response(self, player, timeout): - await asyncio.sleep(timeout) - if self._waiting_for_response[player]: - self.logger.debug( - "waiting for response of type {} timed out".format( - self._waiting_for_response_type[player] - ) - ) - self._waiting_for_response[player] = False - self._waiting_for_response_type[player] = None - - def get_response_type(self, msg: "soco_plugin.message.Command"): - res = None - name = msg["name"] - if name == command.play.Command.ACTION: - res = trigger.play.Trigger.ACTION - elif name == command.stop.Command.ACTION: - res = trigger.stop.Trigger.ACTION - elif name == command.pause.Command.ACTION: - res = trigger.pause.Trigger.ACTION - elif name in ( - command.volume.relative.Command.ACTION, - command.volume.absolute.Command.ACTION, - command.volume.ramp.Command.ACTION, - ): - res = trigger.volume.Trigger.ACTION - return res + self.logger.error("Exception executing action: {}".format(e)) + else: + self.logger.warning("No action found for message: {}".format(msg)) async def writer( self, msgs: Iterable["soco_plugin.message.Command"], *args ) -> None: + self.logger.debug("Writer called") + msg_count = 0 for msg in msgs: + msg_count += 1 + self.logger.info("Processing message {}: {} (type: {})".format(msg_count, msg, type(msg))) if isinstance(msg, Msg): for address in msg["addresses"]: + self.logger.info("Checking address: {} in players: {}".format(address, list(self._players.keys()))) if address in self._players: (player, _, _) = self._players[address] - while True: - if not self._waiting_for_response[player]: - self._waiting_for_response[player] = True - self._waiting_for_response_type[ - player - ] = self.get_response_type(msg) - self._loop.create_task( - self._cancel_waiting_on_response( - player, self.SEND_MESSAGE_TIMEOUT - ), - name="Cancel waiting on response for {}".format(player.player_name) - ) - - self.logger.debug("send message {}".format(msg)) - await self.send_msg(msg, player) - break - else: - await asyncio.sleep(self.POLL_TIMEOUT) + self.logger.info("Sending Sonos command {} to {}".format(msg, address)) + await self.send_msg(msg, player) + else: + self.logger.warning("Address {} not found in players {}".format(address, list(self._players.keys()))) + else: + self.logger.warning("Message is not a Msg instance: {} (type: {})".format(msg, type(msg))) + if msg_count == 0: + self.logger.debug("Writer called with 0 messages") @staticmethod def make_trigger(msg: "soco_plugin.Description") -> "soco_plugin.Trigger": diff --git a/soco_plugin/tests/test_gateway.py b/soco_plugin/tests/test_gateway.py index a13ccbc..e1c41e6 100644 --- a/soco_plugin/tests/test_gateway.py +++ b/soco_plugin/tests/test_gateway.py @@ -29,6 +29,8 @@ async def postpone_gw_running(self): async def asyncSetUp(self): self._gw = soco_plugin.Gateway() + # Make _players dict support iteration for logging + self._gw._players = {} self._loop = asyncio.get_event_loop() self._loop.create_task( self._gw.associate_triggers( @@ -54,12 +56,13 @@ async def test_stopped(self): test = Test("test_stopped") mock = unittest.mock.Mock() + mock.player_name = "Bagno" event_mock = unittest.mock.Mock() event_mock.variables = {"transport_state": "STOPPED"} av_mock = unittest.mock.Mock() av_mock.events.get.return_value = event_mock mock.avTransport.subscribe.return_value = av_mock - with unittest.mock.patch("soco.discovery.by_name") as new_mock: + with unittest.mock.patch("soco.discovery.scan_network_get_by_name") as new_mock: new_mock.return_value = mock test.run() tc.assertIn(Test.STATE_CHANGED, events) @@ -118,12 +121,13 @@ async def test_stopped(self): test = Test("test_stopped") mock = unittest.mock.Mock() + mock.player_name = "Bagno" event_mock = unittest.mock.Mock() event_mock.variables = {"transport_state": "STOPPED"} av_mock = unittest.mock.Mock() av_mock.events.get.return_value = event_mock mock.avTransport.subscribe.return_value = av_mock - with unittest.mock.patch("soco.discovery.by_name") as new_mock: + with unittest.mock.patch("soco.discovery.scan_network_get_by_name") as new_mock: new_mock.return_value = mock test.run() tc.assertIn(Test.STATE_CHANGED, events) diff --git a/soco_plugin/trigger/volume.py b/soco_plugin/trigger/volume.py index 14fafea..64e8c53 100644 --- a/soco_plugin/trigger/volume.py +++ b/soco_plugin/trigger/volume.py @@ -29,6 +29,11 @@ def make_new_state_from( >>> d = soco_plugin.Description(msg) >>> new_state = trigger.make_new_state_from(d, old_state) """ + # Skip volume updates when in fading state + # Volume is constantly changing during fade and incoming values may be stale + if hasattr(old_state, 'is_fading') and old_state.is_fading: + return old_state + new_state = super(Trigger, self).make_new_state_from( another_description, old_state )