Fix reloading of the airplay provider (#767)
authorMarcel van der Veldt <m.vanderveldt@outlook.com>
Mon, 10 Jul 2023 20:57:50 +0000 (22:57 +0200)
committerGitHub <noreply@github.com>
Mon, 10 Jul 2023 20:57:50 +0000 (22:57 +0200)
* Fix some weird flipflop when reloading airplay provider

* adjust logger

music_assistant/server/providers/airplay/__init__.py
music_assistant/server/providers/slimproto/__init__.py
music_assistant/server/providers/slimproto/cli.py

index 7254e5fae1fd3492609a068c4ef7b111f9aa9343..1ee21e12c1ea0fb299f4538cf092f85974338ce6 100644 (file)
@@ -23,7 +23,7 @@ from music_assistant.common.models.config_entries import (
 from music_assistant.common.models.enums import ConfigEntryType
 from music_assistant.common.models.player import DeviceInfo, Player
 from music_assistant.common.models.queue_item import QueueItem
-from music_assistant.constants import CONF_PLAYERS
+from music_assistant.constants import CONF_LOG_LEVEL, CONF_PLAYERS
 from music_assistant.server.models.player_provider import PlayerProvider
 
 if TYPE_CHECKING:
@@ -116,6 +116,7 @@ class AirplayProvider(PlayerProvider):
     _timer_handle: asyncio.TimerHandle | None = None
     _closing: bool = False
     _config_file: str | None = None
+    _log_reader_task: asyncio.Task | None = None
 
     async def handle_setup(self) -> None:
         """Handle async initialization of the provider."""
@@ -349,6 +350,8 @@ class AirplayProvider(PlayerProvider):
             "Starting Airplay bridge using config file %s",
             self._config_file,
         )
+        conf_log_level = self.config.get_value(CONF_LOG_LEVEL)
+        enable_debug_log = conf_log_level == "DEBUG"
         args = [
             self._bridge_bin,
             "-s",
@@ -358,21 +361,20 @@ class AirplayProvider(PlayerProvider):
             "-I",
             "-Z",
             "-d",
-            "all=warn",
+            f'all={"debug" if enable_debug_log else "warn"}',
             # filter out apple tv's for now until we fix auth
             "-m",
             "apple-tv,appletv",
-            # enable terminate on exit otherwise exists are soooo slooooowwww
-            "-k",
         ]
         start_success = False
         while True:
             try:
                 self._bridge_proc = await asyncio.create_subprocess_shell(
                     " ".join(args),
-                    stdout=asyncio.subprocess.DEVNULL,
-                    stderr=asyncio.subprocess.DEVNULL,
+                    stdout=asyncio.subprocess.PIPE,
+                    stderr=asyncio.subprocess.STDOUT,
                 )
+                self._log_reader_task = asyncio.create_task(self._log_reader())
                 await self._bridge_proc.wait()
             except Exception as err:
                 if not start_success:
@@ -394,6 +396,8 @@ class AirplayProvider(PlayerProvider):
                 self.logger.debug("Bridge process stopped.")
             except ProcessLookupError:
                 pass
+        if self._log_reader_task and not self._log_reader_task.done():
+            self._log_reader_task.cancel()
 
     async def _check_config_xml(self, recreate: bool = False) -> None:
         """Check the bridge config XML file."""
@@ -476,6 +480,13 @@ class AirplayProvider(PlayerProvider):
         async with aiofiles.open(self._config_file, "w") as _file:
             await _file.write(ET.tostring(xml_root).decode())
 
+    async def _log_reader(self) -> None:
+        """Read log output from bridge process."""
+        bridge_logger = self.logger.getChild("squeeze2raop")
+        while self._bridge_proc.returncode is None:
+            async for line in self._bridge_proc.stdout:
+                bridge_logger.debug(line.decode().strip())
+
     def restart_bridge(self) -> None:
         """Schedule restart of bridge process."""
         if self._timer_handle is not None:
index 4e499463abc07fd34f0574c06e33694daaa2b1be..3d8e3a5df3d101232885a92486858af0827d50c0 100644 (file)
@@ -224,9 +224,13 @@ class SlimprotoProvider(PlayerProvider):
 
     async def unload(self) -> None:
         """Handle close/cleanup of the provider."""
+        if getattr(self, "_virtual_providers", None):
+            raise RuntimeError("Virtual providers loaded")
         if hasattr(self, "_socket_clients"):
             for client in list(self._socket_clients.values()):
-                client.disconnect()
+                with suppress(RuntimeError):
+                    # this may fail due to a race condition sometimes
+                    client.disconnect()
         self._socket_clients = {}
         if hasattr(self, "_socket_servers"):
             for _server in self._socket_servers:
@@ -772,7 +776,8 @@ class SlimprotoProvider(PlayerProvider):
         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
-            existing.disconnect()
+            with suppress(RuntimeError):
+                existing.disconnect()
 
         self._socket_clients[player_id] = client
         # update all attributes
index ca2841f95012da673e314a71dcf6dbdd84a0e001..84bec41f753538f8cc3df04d231cadbb583430f2 100644 (file)
@@ -183,6 +183,8 @@ class LmsCli:
             while True:
                 raw_request = await reader.readline()
                 raw_request = raw_request.strip().decode("utf-8")
+                if not raw_request:
+                    break
                 # request comes in as url encoded strings, separated by space
                 raw_params = [urllib.parse.unquote(x) for x in raw_request.split(" ")]
                 # the first param is either a macaddress or a command