Add some more debug logging to investigate issues (#819)

diff --git a/music_assistant/server/controllers/players.py b/music_assistant/server/controllers/players.py
index eaf59ad75a9703940bc6a6b3793f4f1ec9a30248..6a8385a859be6dbdd72f0074ee6ff16f92e7d2d0 100755 (executable)
--- a/music_assistant/server/controllers/players.py
+++ b/music_assistant/server/controllers/players.py
@@ -271,6 +271,7 @@ class PlayerController(CoreController):
 
         - player_id: player_id of the player to handle the command.
         """
+        self.logger.debug("Processing STOP command for player %s", player_id)
         player_id = self._check_redirect(player_id)
         if player_provider := self.get_player_provider(player_id):
             await player_provider.cmd_stop(player_id)
@@ -281,6 +282,7 @@ class PlayerController(CoreController):
 
         - player_id: player_id of the player to handle the command.
         """
+        self.logger.debug("Processing PLAY command for player %s", player_id)
         player_id = self._check_redirect(player_id)
         player_provider = self.get_player_provider(player_id)
         await player_provider.cmd_play(player_id)
@@ -291,6 +293,7 @@ class PlayerController(CoreController):
 
         - player_id: player_id of the player to handle the command.
         """
+        self.logger.debug("Processing PAUSE command for player %s", player_id)
         player_id = self._check_redirect(player_id)
         player_provider = self.get_player_provider(player_id)
         await player_provider.cmd_pause(player_id)
@@ -335,6 +338,9 @@ class PlayerController(CoreController):
         - player_id: player_id of the player to handle the command.
         - powered: bool if player should be powered on or off.
         """
+        self.logger.debug(
+            "Processing POWER %s command for player %s", "ON" if powered else "OFF", player_id
+        )
         # TODO: Implement PlayerControl
         player = self.get(player_id, True)
 
@@ -404,6 +410,7 @@ class PlayerController(CoreController):
         - player_id: player_id of the player to handle the command.
         - volume_level: volume level (0..100) to set on the player.
         """
+        self.logger.debug("Processing VOLUME_SET command for player %s", player_id)
         # TODO: Implement PlayerControl
         player = self.get(player_id, True)
         if player.type == PlayerType.GROUP:
@@ -468,6 +475,7 @@ class PlayerController(CoreController):
         - player_id: player_id of the player to handle the command.
         - muted: bool if player should be muted.
         """
+        self.logger.debug("Processing VOLUME_MUTE command for player %s", player_id)
         player = self.get(player_id, True)
         assert player
         if PlayerFeature.VOLUME_MUTE not in player.supported_features:
@@ -499,6 +507,7 @@ class PlayerController(CoreController):
             - player_id: player_id of the player to handle the command.
             - target_player: player_id of the syncgroup master or group player.
         """
+        self.logger.debug("Processing SYNC command for player %s", player_id)
         child_player = self.get(player_id, True)
         parent_player = self.get(target_player, True)
         assert child_player
@@ -541,6 +550,7 @@ class PlayerController(CoreController):
 
             - player_id: player_id of the player to handle the command.
         """
+        self.logger.debug("Processing UNSYNC command for player %s", player_id)
         player = self.get(player_id, True)
         if PlayerFeature.SYNC not in player.supported_features:
             raise UnsupportedFeaturedException(f"Player {player.name} does not support syncing")

diff --git a/music_assistant/server/providers/slimproto/__init__.py b/music_assistant/server/providers/slimproto/__init__.py
index 013589b5490ef47a04fb33d549b49b42275362a2..d26238b790e8a4169234acc50e7d9849fc8e4688 100644 (file)
--- a/music_assistant/server/providers/slimproto/__init__.py
+++ b/music_assistant/server/providers/slimproto/__init__.py
@@ -764,9 +764,14 @@ class SlimprotoProvider(PlayerProvider):
     async def _handle_connected(self, client: SlimClient) -> None:
         """Handle a client connected event."""
         player_id = client.player_id
+        self.logger.warning("Player %s connected", client.name or player_id)
         if existing := self._socket_clients.pop(player_id, None):
             # race condition: new socket client connected while
             # the old one has not yet been cleaned up
+            self.logger.warning(
+                "Player %s connected while previous session still existing!",
+                client.name or player_id,
+            )
             with suppress(RuntimeError):
                 existing.disconnect()
 
@@ -798,6 +803,10 @@ class SlimprotoProvider(PlayerProvider):
             await self.mass.cache.set(
                 f"{CACHE_KEY_PREV_STATE}.{player_id}", (client.powered, client.volume_level)
             )
+            self.logger.warning(
+                "Player %s disconnected",
+                client.name or player_id,
+            )
         if player := self.mass.players.get(player_id):
             player.available = False
             self.mass.players.update(player_id)

diff --git a/music_assistant/server/providers/ugp/__init__.py b/music_assistant/server/providers/ugp/__init__.py
index ca4561c5a28e11ee0afc6c3cc4b840303c8ffff2..21bc2e8e350c8f6697936a74ae0b62262829d852 100644 (file)
--- a/music_assistant/server/providers/ugp/__init__.py
+++ b/music_assistant/server/providers/ugp/__init__.py
@@ -421,6 +421,9 @@ class UniversalGroupProvider(PlayerProvider):
 
         # if the last player of a group turned off, turn off the group
         if len(powered_childs) == 0:
+            self.logger.debug(
+                "Group %s has no more powered members, turning off group player", player_id
+            )
             self.mass.create_task(self.cmd_power, player_id, False)
             return False
 
@@ -444,11 +447,17 @@ class UniversalGroupProvider(PlayerProvider):
             ):
                 # prevent resume when player platform supports sync
                 # and one of its players is already playing
+                self.logger.debug(
+                    "Groupplayer %s forced resync due to groupmember change", player_id
+                )
                 self.mass.create_task(
                     self.mass.players.cmd_sync, child_player.player_id, sync_leader
                 )
             else:
-                # send atcive source because the group may be within another group
+                # send active source because the group may be within another group
+                self.logger.debug(
+                    "Groupplayer %s forced resume due to groupmember change", player_id
+                )
                 self.mass.create_task(self.mass.player_queues.resume, group_player.active_source)
         elif (
             not new_power
@@ -459,6 +468,7 @@ class UniversalGroupProvider(PlayerProvider):
             # a sync master player turned OFF while the group player
             # should still be playing - we need to resync/resume
             # send atcive source because the group may be within another group
+            self.logger.debug("Groupplayer %s forced resume due to groupmember change", player_id)
             self.mass.create_task(self.mass.player_queues.resume, group_player.active_source)
 
     def _get_active_members(