From b70b30e9272f0a122bccf7148198d267591f25e1 Mon Sep 17 00:00:00 2001 From: Marcel van der Veldt Date: Fri, 4 Aug 2023 03:02:40 +0200 Subject: [PATCH] Add some more debug logging to investigate issues (#819) --- music_assistant/server/controllers/players.py | 10 ++++++++++ .../server/providers/slimproto/__init__.py | 9 +++++++++ music_assistant/server/providers/ugp/__init__.py | 12 +++++++++++- 3 files changed, 30 insertions(+), 1 deletion(-) diff --git a/music_assistant/server/controllers/players.py b/music_assistant/server/controllers/players.py index eaf59ad7..6a8385a8 100755 --- 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 013589b5..d26238b7 100644 --- 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 ca4561c5..21bc2e8e 100644 --- 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( -- 2.34.1