Update pyheos and log service errors in HEOS integration (#23222)

* Update pyheos and command error handling

* Correct comment and remove unnecessary autospec

homeassistant/components/heos/manifest.json

@@ -3,7 +3,7 @@
   "name": "Heos",
   "documentation": "https://www.home-assistant.io/components/heos",
   "requirements": [
-    "pyheos==0.3.1"
+    "pyheos==0.4.0"
   ],
   "dependencies": [],
   "codeowners": [

homeassistant/components/heos/media_player.py

@@ -1,5 +1,6 @@
 """Denon HEOS Media Player."""
-from functools import reduce
+from functools import reduce, wraps
+import logging
 from operator import ior
 from typing import Sequence
 
@@ -21,6 +22,8 @@ BASE_SUPPORTED_FEATURES = SUPPORT_VOLUME_MUTE | SUPPORT_VOLUME_SET | \
                           SUPPORT_VOLUME_STEP | SUPPORT_CLEAR_PLAYLIST | \
                           SUPPORT_SHUFFLE_SET | SUPPORT_SELECT_SOURCE
 
+_LOGGER = logging.getLogger(__name__)
+
 
 async def async_setup_platform(
         hass, config, async_add_entities, discovery_info=None):
@@ -36,6 +39,20 @@ async def async_setup_entry(hass: HomeAssistantType, entry: ConfigEntry,
     async_add_entities(devices, True)
 
 
+def log_command_error(command: str):
+    """Return decorator that logs command failure."""
+    def decorator(func):
+        @wraps(func)
+        async def wrapper(*args, **kwargs):
+            from pyheos import CommandError
+            try:
+                await func(*args, **kwargs)
+            except CommandError as ex:
+                _LOGGER.error("Unable to %s: %s", command, ex)
+        return wrapper
+    return decorator
+
+
 class HeosMediaPlayer(MediaPlayerDevice):
     """The HEOS player."""
 
@@ -101,42 +118,52 @@ class HeosMediaPlayer(MediaPlayerDevice):
             self.hass.helpers.dispatcher.async_dispatcher_connect(
                 SIGNAL_HEOS_SOURCES_UPDATED, self._sources_updated))
 
+    @log_command_error("clear playlist")
     async def async_clear_playlist(self):
         """Clear players playlist."""
         await self._player.clear_queue()
 
+    @log_command_error("pause")
     async def async_media_pause(self):
         """Send pause command."""
         await self._player.pause()
 
+    @log_command_error("play")
     async def async_media_play(self):
         """Send play command."""
         await self._player.play()
 
+    @log_command_error("move to previous track")
     async def async_media_previous_track(self):
         """Send previous track command."""
         await self._player.play_previous()
 
+    @log_command_error("move to next track")
     async def async_media_next_track(self):
         """Send next track command."""
         await self._player.play_next()
 
+    @log_command_error("stop")
     async def async_media_stop(self):
         """Send stop command."""
         await self._player.stop()
 
+    @log_command_error("set mute")
     async def async_mute_volume(self, mute):
         """Mute the volume."""
         await self._player.set_mute(mute)
 
+    @log_command_error("select source")
     async def async_select_source(self, source):
         """Select input source."""
         await self._source_manager.play_source(source, self._player)
 
+    @log_command_error("set shuffle")
     async def async_set_shuffle(self, shuffle):
         """Enable/disable shuffle mode."""
         await self._player.set_play_mode(self._player.repeat, shuffle)
 
+    @log_command_error("set volume level")
     async def async_set_volume_level(self, volume):
         """Set volume level, range 0..1."""
         await self._player.set_volume(int(volume * 100))

requirements_all.txt

@@ -1082,7 +1082,7 @@ pygtt==1.1.2
 pyhaversion==2.2.0
 
 # homeassistant.components.heos
-pyheos==0.3.1
+pyheos==0.4.0
 
 # homeassistant.components.hikvision
 pyhik==0.2.2

requirements_test_all.txt

@@ -220,7 +220,7 @@ pydeconz==54
 pydispatcher==2.0.5
 
 # homeassistant.components.heos
-pyheos==0.3.1
+pyheos==0.4.0
 
 # homeassistant.components.homematic
 pyhomematic==0.1.58

tests/components/heos/conftest.py

@@ -44,7 +44,7 @@ def config_fixture():
 @pytest.fixture(name="players")
 def player_fixture(dispatcher):
     """Create a mock HeosPlayer."""
-    player = Mock(HeosPlayer, autospec=True)
+    player = Mock(HeosPlayer)
     player.heos.dispatcher = dispatcher
     player.player_id = 1
     player.name = "Test Player"
@@ -77,11 +77,11 @@ def player_fixture(dispatcher):
 @pytest.fixture(name="favorites")
 def favorites_fixture() -> Dict[int, HeosSource]:
     """Create favorites fixture."""
-    station = Mock(HeosSource, autospec=True)
+    station = Mock(HeosSource)
     station.type = const.TYPE_STATION
     station.name = "Today's Hits Radio"
     station.media_id = '123456789'
-    radio = Mock(HeosSource, autospec=True)
+    radio = Mock(HeosSource)
     radio.type = const.TYPE_STATION
     radio.name = "Classical MPR (Classical Music)"
     radio.media_id = 's1234'
@@ -94,7 +94,7 @@ def favorites_fixture() -> Dict[int, HeosSource]:
 @pytest.fixture(name="input_sources")
 def input_sources_fixture() -> Sequence[InputSource]:
     """Create a set of input sources for testing."""
-    source = Mock(InputSource, autospec=True)
+    source = Mock(InputSource)
     source.player_id = 1
     source.input_name = const.INPUT_AUX_IN_1
     source.name = "HEOS Drive - Line In 1"

tests/components/heos/test_media_player.py

@@ -1,7 +1,7 @@
 """Tests for the Heos Media Player platform."""
 import asyncio
 
-from pyheos import const
+from pyheos import const, CommandError
 
 from homeassistant.components.heos import media_player
 from homeassistant.components.heos.const import (
@@ -162,67 +162,142 @@ async def test_updates_from_user_changed(
     assert state.attributes[ATTR_INPUT_SOURCE_LIST] == source_list
 
 
-async def test_services(hass, config_entry, config, controller):
+async def test_clear_playlist(hass, config_entry, config, controller, caplog):
-    """Tests player commands."""
+    """Test the clear playlist service."""
     await setup_platform(hass, config_entry, config)
     player = controller.players[1]
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_CLEAR_PLAYLIST,
+            {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+        assert player.clear_queue.call_count == 1
+        player.clear_queue.reset_mock()
+        player.clear_queue.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to clear playlist: Failure (1)" in caplog.text
 
-    await hass.services.async_call(
-        MEDIA_PLAYER_DOMAIN, SERVICE_CLEAR_PLAYLIST,
-        {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
-    assert player.clear_queue.call_count == 1
 
-    player.reset_mock()
+async def test_pause(hass, config_entry, config, controller, caplog):
-    await hass.services.async_call(
+    """Test the pause service."""
-        MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_PAUSE,
+    await setup_platform(hass, config_entry, config)
-        {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+    player = controller.players[1]
-    assert player.pause.call_count == 1
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_PAUSE,
+            {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+        assert player.pause.call_count == 1
+        player.pause.reset_mock()
+        player.pause.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to pause: Failure (1)" in caplog.text
 
-    player.reset_mock()
-    await hass.services.async_call(
-        MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_PLAY,
-        {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
-    assert player.play.call_count == 1
 
-    player.reset_mock()
+async def test_play(hass, config_entry, config, controller, caplog):
-    await hass.services.async_call(
+    """Test the play service."""
-        MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_PREVIOUS_TRACK,
+    await setup_platform(hass, config_entry, config)
-        {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+    player = controller.players[1]
-    assert player.play_previous.call_count == 1
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_PLAY,
+            {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+        assert player.play.call_count == 1
+        player.play.reset_mock()
+        player.play.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to play: Failure (1)" in caplog.text
 
-    player.reset_mock()
-    await hass.services.async_call(
-        MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_NEXT_TRACK,
-        {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
-    assert player.play_next.call_count == 1
 
-    player.reset_mock()
+async def test_previous_track(hass, config_entry, config, controller, caplog):
-    await hass.services.async_call(
+    """Test the previous track service."""
-        MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_STOP,
+    await setup_platform(hass, config_entry, config)
-        {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+    player = controller.players[1]
-    assert player.stop.call_count == 1
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_PREVIOUS_TRACK,
+            {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+        assert player.play_previous.call_count == 1
+        player.play_previous.reset_mock()
+        player.play_previous.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to move to previous track: Failure (1)" in caplog.text
 
-    player.reset_mock()
-    await hass.services.async_call(
-        MEDIA_PLAYER_DOMAIN, SERVICE_VOLUME_MUTE,
-        {ATTR_ENTITY_ID: 'media_player.test_player',
-         ATTR_MEDIA_VOLUME_MUTED: True}, blocking=True)
-    player.set_mute.assert_called_once_with(True)
 
-    player.reset_mock()
+async def test_next_track(hass, config_entry, config, controller, caplog):
-    await hass.services.async_call(
+    """Test the next track service."""
-        MEDIA_PLAYER_DOMAIN, SERVICE_SHUFFLE_SET,
+    await setup_platform(hass, config_entry, config)
-        {ATTR_ENTITY_ID: 'media_player.test_player',
+    player = controller.players[1]
-         ATTR_MEDIA_SHUFFLE: True}, blocking=True)
+    # First pass completes successfully, second pass raises command error
-    player.set_play_mode.assert_called_once_with(player.repeat, True)
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_NEXT_TRACK,
+            {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+        assert player.play_next.call_count == 1
+        player.play_next.reset_mock()
+        player.play_next.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to move to next track: Failure (1)" in caplog.text
 
-    player.reset_mock()
+
-    await hass.services.async_call(
+async def test_stop(hass, config_entry, config, controller, caplog):
-        MEDIA_PLAYER_DOMAIN, SERVICE_VOLUME_SET,
+    """Test the stop service."""
-        {ATTR_ENTITY_ID: 'media_player.test_player',
+    await setup_platform(hass, config_entry, config)
-         ATTR_MEDIA_VOLUME_LEVEL: 1}, blocking=True)
+    player = controller.players[1]
-    player.set_volume.assert_called_once_with(100)
+    # First pass completes successfully, second pass raises command error
-    assert isinstance(player.set_volume.call_args[0][0], int)
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_MEDIA_STOP,
+            {ATTR_ENTITY_ID: 'media_player.test_player'}, blocking=True)
+        assert player.stop.call_count == 1
+        player.stop.reset_mock()
+        player.stop.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to stop: Failure (1)" in caplog.text
+
+
+async def test_volume_mute(hass, config_entry, config, controller, caplog):
+    """Test the volume mute service."""
+    await setup_platform(hass, config_entry, config)
+    player = controller.players[1]
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_VOLUME_MUTE,
+            {ATTR_ENTITY_ID: 'media_player.test_player',
+             ATTR_MEDIA_VOLUME_MUTED: True}, blocking=True)
+        assert player.set_mute.call_count == 1
+        player.set_mute.reset_mock()
+        player.set_mute.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to set mute: Failure (1)" in caplog.text
+
+
+async def test_shuffle_set(hass, config_entry, config, controller, caplog):
+    """Test the shuffle set service."""
+    await setup_platform(hass, config_entry, config)
+    player = controller.players[1]
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_SHUFFLE_SET,
+            {ATTR_ENTITY_ID: 'media_player.test_player',
+             ATTR_MEDIA_SHUFFLE: True}, blocking=True)
+        player.set_play_mode.assert_called_once_with(player.repeat, True)
+        player.set_play_mode.reset_mock()
+        player.set_play_mode.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to set shuffle: Failure (1)" in caplog.text
+
+
+async def test_volume_set(hass, config_entry, config, controller, caplog):
+    """Test the volume set service."""
+    await setup_platform(hass, config_entry, config)
+    player = controller.players[1]
+    # First pass completes successfully, second pass raises command error
+    for _ in range(2):
+        await hass.services.async_call(
+            MEDIA_PLAYER_DOMAIN, SERVICE_VOLUME_SET,
+            {ATTR_ENTITY_ID: 'media_player.test_player',
+             ATTR_MEDIA_VOLUME_LEVEL: 1}, blocking=True)
+        player.set_volume.assert_called_once_with(100)
+        player.set_volume.reset_mock()
+        player.set_volume.side_effect = CommandError(None, "Failure", 1)
+    assert "Unable to set volume level: Failure (1)" in caplog.text
 
 
 async def test_select_favorite(
@@ -270,6 +345,22 @@ async def test_select_radio_favorite(
     assert state.attributes[ATTR_INPUT_SOURCE] == favorite.name
 
 
+async def test_select_radio_favorite_command_error(
+        hass, config_entry, config, controller, favorites, caplog):
+    """Tests command error loged when playing favorite."""
+    await setup_platform(hass, config_entry, config)
+    player = controller.players[1]
+    # Test set radio preset
+    favorite = favorites[2]
+    player.play_favorite.side_effect = CommandError(None, "Failure", 1)
+    await hass.services.async_call(
+        MEDIA_PLAYER_DOMAIN, SERVICE_SELECT_SOURCE,
+        {ATTR_ENTITY_ID: 'media_player.test_player',
+         ATTR_INPUT_SOURCE: favorite.name}, blocking=True)
+    player.play_favorite.assert_called_once_with(2)
+    assert "Unable to select source: Failure (1)" in caplog.text
+
+
 async def test_select_input_source(
         hass, config_entry, config, controller, input_sources):
     """Tests selecting input source and state."""
@@ -304,6 +395,21 @@ async def test_select_input_unknown(
     assert "Unknown source: Unknown" in caplog.text
 
 
+async def test_select_input_command_error(
+        hass, config_entry, config, controller, caplog, input_sources):
+    """Tests selecting an unknown input."""
+    await setup_platform(hass, config_entry, config)
+    player = controller.players[1]
+    input_source = input_sources[0]
+    player.play_input_source.side_effect = CommandError(None, "Failure", 1)
+    await hass.services.async_call(
+        MEDIA_PLAYER_DOMAIN, SERVICE_SELECT_SOURCE,
+        {ATTR_ENTITY_ID: 'media_player.test_player',
+         ATTR_INPUT_SOURCE: input_source.name}, blocking=True)
+    player.play_input_source.assert_called_once_with(input_source)
+    assert "Unable to select source: Failure (1)" in caplog.text
+
+
 async def test_unload_config_entry(hass, config_entry, config, controller):
     """Test the player is removed when the config entry is unloaded."""
     await setup_platform(hass, config_entry, config)