Small logging tweaks

diff --git a/music_assistant/controllers/streams.py b/music_assistant/controllers/streams.py
index d4cbaebe001d3757e51d3ddb877370fc7cd101a5..fda520399cf87e19da6cf01d44c88a9308d15bec 100644 (file)
--- a/music_assistant/controllers/streams.py
+++ b/music_assistant/controllers/streams.py
@@ -794,7 +794,7 @@ class StreamsController(CoreController):
         # like https hosts and it also offers the pre-announce 'bell'
         return f"{self.base_url}/announcement/{player_id}.{content_type.value}"
 
-    @use_buffer(30, 4)
+    @use_buffer(30, 2)
     async def get_queue_flow_stream(
         self,
         queue: PlayerQueue,
@@ -1119,9 +1119,9 @@ class StreamsController(CoreController):
             "Starting queue item stream for %s (%s)"
             " - using buffer: %s"
             " - using fade-in: %s"
-            " - volume normalization: %s",
+            " - using volume normalization: %s",
             queue_item.name,
-            queue_item.uri,
+            queue_item.streamdetails.uri,
             allow_buffer,
             streamdetails.fade_in,
             streamdetails.volume_normalization_mode,
@@ -1147,6 +1147,7 @@ class StreamsController(CoreController):
         fade_in_buffer = b""
         bytes_received = 0
         aborted = False
+        stream_started_at = asyncio.get_event_loop().time()
         try:
             async for chunk in media_stream_gen:
                 bytes_received += len(chunk)
@@ -1157,6 +1158,12 @@ class StreamsController(CoreController):
                     self.mass.player_queues.track_loaded_in_buffer(
                         queue_item.queue_id, queue_item.queue_item_id
                     )
+                    self.logger.debug(
+                        "First audio chunk received for %s (%s) after %.2f seconds",
+                        queue_item.name,
+                        queue_item.streamdetails.uri,
+                        asyncio.get_event_loop().time() - stream_started_at,
+                    )
                 # handle optional fade-in
                 if streamdetails.fade_in:
                     if len(fade_in_buffer) < pcm_format.pcm_sample_size * 4:
@@ -1184,9 +1191,10 @@ class StreamsController(CoreController):
             seconds_streamed = bytes_received / pcm_format.pcm_sample_size
             streamdetails.seconds_streamed = seconds_streamed
             self.logger.debug(
-                "stream %s for %s - seconds streamed: %s",
+                "stream %s for %s in %.2f seconds - seconds streamed: %s",
                 "aborted" if aborted else "finished",
                 streamdetails.uri,
+                asyncio.get_event_loop().time() - stream_started_at,
                 seconds_streamed,
             )
             # report stream to provider
@@ -1200,7 +1208,7 @@ class StreamsController(CoreController):
             loop = asyncio.get_running_loop()
             await loop.run_in_executor(None, gc.collect)
 
-    @use_buffer(30, 4)
+    @use_buffer(30, 2)
     async def get_queue_item_stream_with_smartfade(
         self,
         queue_item: QueueItem,

diff --git a/music_assistant/helpers/audio.py b/music_assistant/helpers/audio.py
index dd5ce2ae079973121830d3240c71970e0bed8add..3f8d3929ee35049a9ba76f5b197b327a1c6a8328 100644 (file)
--- a/music_assistant/helpers/audio.py
+++ b/music_assistant/helpers/audio.py
@@ -429,8 +429,9 @@ async def get_media_stream_with_buffer(
     filter_params: list[str] | None = None,
 ) -> AsyncGenerator[bytes, None]:
     """Get audio stream for given media details as raw PCM with buffering."""
-    LOGGER.debug(
-        "get_media_stream_with_buffer: Starting for %s (seek: %s)",
+    LOGGER.log(
+        VERBOSE_LOG_LEVEL,
+        "buffered_media_stream: Starting for %s (seek: %s)",
         streamdetails.uri,
         seek_position,
     )
@@ -477,8 +478,7 @@ async def get_media_stream_with_buffer(
         if not existing_buffer.is_valid(checksum, seek_position):
             LOGGER.log(
                 VERBOSE_LOG_LEVEL,
-                "get_media_stream_with_buffer: Existing buffer invalid for %s "
-                "(seek: %s, discarded: %s)",
+                "buffered_media_stream: Existing buffer invalid for %s (seek: %s, discarded: %s)",
                 streamdetails.uri,
                 seek_position,
                 existing_buffer._discarded_chunks,
@@ -488,7 +488,7 @@ async def get_media_stream_with_buffer(
             existing_buffer = None
         else:
             LOGGER.debug(
-                "get_media_stream_with_buffer: Reusing existing buffer for %s - "
+                "buffered_media_stream: Reusing existing buffer for %s - "
                 "available: %ss, seek: %s, discarded: %s",
                 streamdetails.uri,
                 existing_buffer.seconds_available,
@@ -503,8 +503,8 @@ async def get_media_stream_with_buffer(
         # otherwise we would need to fill the buffer up to the seek position first
         # which is not efficient.
         LOGGER.debug(
-            "get_media_stream_with_buffer: No existing buffer and seek >60s for %s, "
-            "starting normal stream",
+            "buffered_media_stream: No existing buffer and seek >60s for %s, "
+            "starting normal (unbuffered) stream",
             streamdetails.uri,
         )
         async for chunk in get_media_stream(
@@ -520,7 +520,7 @@ async def get_media_stream_with_buffer(
     if not existing_buffer:
         # create new audio buffer and start fill task
         LOGGER.debug(
-            "get_media_stream_with_buffer: Creating new buffer for %s",
+            "buffered_media_stream: Creating new buffer for %s",
             streamdetails.uri,
         )
         audio_buffer = AudioBuffer(pcm_format, checksum)
@@ -537,7 +537,7 @@ async def get_media_stream_with_buffer(
     finally:
         LOGGER.log(
             VERBOSE_LOG_LEVEL,
-            "get_media_stream_with_buffer: Completed, yielded %s chunks",
+            "buffered_media_stream: Completed, yielded %s chunks",
             chunk_count,
         )