Airplay fixes (#1091)

diff --git a/music_assistant/server/models/provider.py b/music_assistant/server/models/provider.py
index c4ae5cfc5b69599072e396a5bf422c87e2bcacc2..e31677503ccbdd342644f645fe3dd04195d491ac 100644 (file)
--- a/music_assistant/server/models/provider.py
+++ b/music_assistant/server/models/provider.py
@@ -25,7 +25,7 @@ class Provider:
         self.manifest = manifest
         self.config = config
         mass_logger = logging.getLogger(ROOT_LOGGER_NAME)
-        self.logger = mass_logger.getChild(f"providers.{self.domain}")
+        self.logger = mass_logger.getChild(f"providers.{self.instance_id}")
         log_level = config.get_value(CONF_LOG_LEVEL)
         if log_level == "GLOBAL":
             self.logger.setLevel(mass_logger.level)

diff --git a/music_assistant/server/providers/airplay/__init__.py b/music_assistant/server/providers/airplay/__init__.py
index 643f8bd53138ec0367b0eea9e941112d64a64f1c..9cdd29ea474a1975e933b74ed142ff2ac5aa2f49 100644 (file)
--- a/music_assistant/server/providers/airplay/__init__.py
+++ b/music_assistant/server/providers/airplay/__init__.py
@@ -2,6 +2,7 @@
 from __future__ import annotations
 
 import asyncio
+import logging
 import os
 import platform
 import socket
@@ -246,7 +247,6 @@ class AirPlayPlayer(DeviceListener):
         def send_data():
             with open(named_pipe, "w") as f:
                 f.write(command)
-                f.flush()
 
         self.logger.debug("sending command %s", command)
         await self.mass.create_task(send_data)
@@ -490,6 +490,8 @@ class AirplayProvider(PlayerProvider):
         self._cliraop_bin = await self.get_cliraop_binary()
         self.mass.create_task(self._run_discovery())
         dacp_port = await select_free_port(39831, 49831)
+        # the pyatv logger is way to noisy, silence it a bit
+        logging.getLogger("pyatv").setLevel(self.logger.level + 10)
         self.dacp_id = dacp_id = f"{randrange(2 ** 64):X}"
         self.logger.debug("Starting DACP ActiveRemote %s on port %s", dacp_id, dacp_port)
         self._dacp_server = await asyncio.start_server(
@@ -740,11 +742,6 @@ class AirplayProvider(PlayerProvider):
                         if prev_metadata_checksum != metadata_checksum:
                             prev_metadata_checksum = metadata_checksum
                             self.mass.create_task(self._send_metadata(player_id))
-                    # send progress metadata
-                    for atv_player in self._get_sync_clients(player_id):
-                        self.mass.create_task(
-                            atv_player.send_cli_command(f"PROGRESS={int(queue.elapsed_time)}\n")
-                        )
 
                     # send audio chunk to player(s)
                     async with asyncio.TaskGroup() as tg:
@@ -758,6 +755,15 @@ class AirplayProvider(PlayerProvider):
                         if not available_clients:
                             return
 
+                        # send progress metadata
+                        if queue.elapsed_time:
+                            for atv_player in self._get_sync_clients(player_id):
+                                tg.create_task(
+                                    atv_player.send_cli_command(
+                                        f"PROGRESS={int(queue.elapsed_time)}\n"
+                                    )
+                                )
+
             finally:
                 self.logger.debug("Streamer task ended for player %s", queue.display_name)
                 for atv_player in self._get_sync_clients(player_id):
@@ -799,7 +805,7 @@ class AirplayProvider(PlayerProvider):
         atv_player = self._atv_players[player_id]
         if atv_player.cliraop_proc:
             # prefer interactive command to our streamer
-            await atv_player.send_cli_command(f"VOLUME={volume_level}")
+            await atv_player.send_cli_command(f"VOLUME={volume_level}\n")
         elif atv := atv_player.atv:
             await atv.audio.set_volume(volume_level)
 
@@ -848,7 +854,7 @@ class AirplayProvider(PlayerProvider):
         try:
             self._discovery_running = True
             self.logger.debug("Airplay discovery started...")
-            discovered_devices = await scan(self.mass.loop, timeout=5)
+            discovered_devices = await scan(self.mass.loop, protocol=Protocol.RAOP, timeout=30)
 
             if not discovered_devices:
                 self.logger.debug("No devices found")
@@ -996,6 +1002,8 @@ class AirplayProvider(PlayerProvider):
         sync_adjust = self.mass.config.get_raw_player_config_value(
             atv_player.player_id, CONF_SYNC_ADJUST, 0
         )
+        if self.logger.level == logging.DEBUG:
+            extra_args += ["-d", "5"]
 
         atv_player.optimistic_state = PlayerState.PLAYING
         # always generate a new active remote id to prevent race conditions
@@ -1027,8 +1035,6 @@ class AirplayProvider(PlayerProvider):
             args, enable_stdin=True, enable_stdout=False, enable_stderr=True
         )
         await atv_player.cliraop_proc.start()
-        # send empty command to unblock named pipe
-        await atv_player.send_cli_command("\n")
         atv_player.cliraop_proc.attach_task(log_watcher(atv_player.cliraop_proc))
 
     async def _send_metadata(self, player_id: str) -> None:
@@ -1061,26 +1067,22 @@ class AirplayProvider(PlayerProvider):
         for atv_player in self._get_sync_clients(player_id):
             await atv_player.send_cli_command(cmd)
 
-        # temp test for not sending artwork
-        exists_func = wrap(os.path.exists)
-        if await exists_func("/tmp/do_not_send_artwork"):  # noqa: S108
-            return
-
         # get image
         if not queue.current_item.image:
             return
-        image_path = f"/tmp/{shortuuid.random(12)}"  # noqa: S108
+        temp_image_path = f"/tmp/{shortuuid.random(12)}"  # noqa: S108
         image_data = await self.mass.metadata.get_thumbnail(
             queue.current_item.image.path,
             512,
             queue.current_item.image.provider,
         )
-        async with aiofiles.open(image_path, "wb") as outfile:
+        if not image_data:
+            return
+        async with aiofiles.open(temp_image_path, "wb") as outfile:
             await outfile.write(image_data)
         for atv_player in self._get_sync_clients(player_id):
-            if image_path:
-                await atv_player.send_cli_command(f"ARTWORK={image_path}\n")
+            await atv_player.send_cli_command(f"ARTWORK={temp_image_path}\n")
         # make sure the temp file gets deleted again
-        await asyncio.sleep(10)
+        await asyncio.sleep(30)
         rm_func = wrap(os.remove)
-        await rm_func(image_path)
+        await rm_func(temp_image_path)

diff --git a/music_assistant/server/providers/chromecast/__init__.py b/music_assistant/server/providers/chromecast/__init__.py
index 6b379735f8ed3428b5cc3a5dacb6e738f1713f2d..fa300edf9a0f4b95e5aac94dd8fd40374f00c3b3 100644 (file)
--- a/music_assistant/server/providers/chromecast/__init__.py
+++ b/music_assistant/server/providers/chromecast/__init__.py
@@ -13,17 +13,10 @@ from typing import TYPE_CHECKING
 from uuid import UUID
 
 import pychromecast
-from pychromecast.controllers.media import (
-    STREAM_TYPE_BUFFERED,
-    STREAM_TYPE_LIVE,
-    MediaController,
-)
+from pychromecast.controllers.media import STREAM_TYPE_BUFFERED, STREAM_TYPE_LIVE, MediaController
 from pychromecast.controllers.multizone import MultizoneController, MultizoneManager
 from pychromecast.discovery import CastBrowser, SimpleCastListener
-from pychromecast.socket_client import (
-    CONNECTION_STATUS_CONNECTED,
-    CONNECTION_STATUS_DISCONNECTED,
-)
+from pychromecast.socket_client import CONNECTION_STATUS_CONNECTED, CONNECTION_STATUS_DISCONNECTED
 
 from music_assistant.common.models.config_entries import (
     CONF_ENTRY_CROSSFADE_DURATION,
@@ -41,13 +34,7 @@ from music_assistant.common.models.enums import (
 )
 from music_assistant.common.models.errors import PlayerUnavailableError
 from music_assistant.common.models.player import DeviceInfo, Player
-from music_assistant.constants import (
-    CONF_CROSSFADE,
-    CONF_FLOW_MODE,
-    CONF_LOG_LEVEL,
-    CONF_PLAYERS,
-    MASS_LOGO_ONLINE,
-)
+from music_assistant.constants import CONF_CROSSFADE, CONF_FLOW_MODE, CONF_PLAYERS, MASS_LOGO_ONLINE
 from music_assistant.server.models.player_provider import PlayerProvider
 
 from .helpers import CastStatusListener, ChromecastInfo
@@ -58,10 +45,7 @@ if TYPE_CHECKING:
     from pychromecast.models import CastInfo
     from pychromecast.socket_client import ConnectionStatus
 
-    from music_assistant.common.models.config_entries import (
-        PlayerConfig,
-        ProviderConfig,
-    )
+    from music_assistant.common.models.config_entries import PlayerConfig, ProviderConfig
     from music_assistant.common.models.provider import ProviderManifest
     from music_assistant.common.models.queue_item import QueueItem
     from music_assistant.server import MusicAssistant
@@ -165,11 +149,7 @@ class ChromecastProvider(PlayerProvider):
             self.mass.zeroconf,
         )
         # silence pychromecast logging
-        log_level = self.config.get_value(CONF_LOG_LEVEL)
-        if log_level == "DEBUG":
-            logging.getLogger("pychromecast").setLevel(logging.DEBUG)
-        else:
-            logging.getLogger("pychromecast").setLevel(logging.INFO)
+        logging.getLogger("pychromecast").setLevel(self.logger.level + 10)
         # start discovery in executor
         await self.mass.loop.run_in_executor(None, self.browser.start_discovery)
 

diff --git a/music_assistant/server/providers/dlna/__init__.py b/music_assistant/server/providers/dlna/__init__.py
index 79931a96533b78b41546a5bcb72f1785b034ed6a..0dab2ddba8ae3c20bb9fc5f7cbd4b8a2d8a55924 100644 (file)
--- a/music_assistant/server/providers/dlna/__init__.py
+++ b/music_assistant/server/providers/dlna/__init__.py
@@ -10,6 +10,7 @@ from __future__ import annotations
 
 import asyncio
 import functools
+import logging
 import time
 from contextlib import suppress
 from dataclasses import dataclass, field
@@ -49,10 +50,7 @@ if TYPE_CHECKING:
     from async_upnp_client.client import UpnpRequester, UpnpService, UpnpStateVariable
     from async_upnp_client.utils import CaseInsensitiveDict
 
-    from music_assistant.common.models.config_entries import (
-        PlayerConfig,
-        ProviderConfig,
-    )
+    from music_assistant.common.models.config_entries import PlayerConfig, ProviderConfig
     from music_assistant.common.models.provider import ProviderManifest
     from music_assistant.common.models.queue_item import QueueItem
     from music_assistant.server import MusicAssistant
@@ -283,6 +281,8 @@ class DLNAPlayerProvider(PlayerProvider):
         """Handle async initialization of the provider."""
         self.dlnaplayers = {}
         self.lock = asyncio.Lock()
+        # silence the async_upnp_client logger
+        logging.getLogger("async_upnp_client").setLevel(self.logger.level + 10)
         self.requester = AiohttpSessionRequester(self.mass.http_session, with_sleep=True)
         self.upnp_factory = UpnpFactory(self.requester, non_strict=True)
         self.notify_server = DLNANotifyServer(self.requester, self.mass)