From ed0bbfbf69fb0e20f894ca5a4c7922043f78828c Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Fri, 7 Nov 2025 08:29:20 +0000
Subject: [PATCH] Add FlacCacheSink debug logs - system now works!
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Added comprehensive logging to FlacCacheSink::process():
- Process start
- Waiting for/receiving first audio chunk
- FLAC encoder creation
- Cache ingestion and pump parallel execution
- tokio::join! completion
- Track added to cache confirmation

Testing results show PROGRESSIVE CACHING WORKS:
✅ Prebuffer reached in 0.6 seconds
✅ Track added to cache with pk
✅ Download pipeline completes successfully
✅ Playlist receives track
✅ Playback starts

Current timing:
- t=0.6s: Prebuffer complete (512KB)
- t=3.6s: Track added to playlist (after pump completes)
- t=4.5s: Playback starts

The 3s delay is because tokio::join! waits for BOTH futures:
- cache_future (returns after prebuffer ~0.6s)
- pump_future (pumps entire first track ~3s)

For true 1-2s startup, would need to refactor to push to playlist
immediately after prebuffer, without waiting for pump to complete.
---
 pmoaudio-ext/src/sinks/flac_cache_sink.rs | 17 ++++++++++++++---
 1 file changed, 14 insertions(+), 3 deletions(-)

diff --git a/pmoaudio-ext/src/sinks/flac_cache_sink.rs b/pmoaudio-ext/src/sinks/flac_cache_sink.rs
index 3a6d948f..e5c8cee7 100755
--- a/pmoaudio-ext/src/sinks/flac_cache_sink.rs
+++ b/pmoaudio-ext/src/sinks/flac_cache_sink.rs
@@ -86,16 +86,22 @@ impl NodeLogic for FlacCacheSinkLogic {
         _output: Vec<mpsc::Sender<Arc<AudioSegment>>>,
         stop_token: CancellationToken,
     ) -> Result<(), AudioError> {
+        tracing::debug!("FlacCacheSink::process() started");
         let mut rx = input.expect("FlacCacheSink must have input");
         let mut track_number = 0;
 
         loop {
             // Attendre le premier chunk audio pour cette track
+            tracing::debug!("FlacCacheSink: Waiting for first audio chunk (track_number={})", track_number);
             let (first_segment, track_metadata) =
                 match wait_for_first_audio_chunk_with_metadata(&mut rx, &stop_token).await {
-                    Ok(result) => result,
-                    Err(_) => {
+                    Ok(result) => {
+                        tracing::debug!("FlacCacheSink: Got first audio chunk");
+                        result
+                    }
+                    Err(e) => {
                         // Plus d'audio disponible
+                        tracing::debug!("FlacCacheSink: No more audio available: {}", e);
                         return Ok(());
                     }
                 };
@@ -125,12 +131,14 @@ impl NodeLogic for FlacCacheSinkLogic {
             options_with_metadata.metadata = track_metadata.clone();
 
             // Créer l'encoder
+            tracing::debug!("FlacCacheSink: Creating FLAC encoder");
             let reader = ByteStreamReader::new(pcm_rx);
             let flac_stream = encode_flac_stream(reader, format, options_with_metadata)
                 .await
                 .map_err(|e| {
                     AudioError::ProcessingError(format!("FLAC encode init failed: {}", e))
                 })?;
+            tracing::debug!("FlacCacheSink: FLAC encoder created");
 
             // Ingérer le FLAC progressivement dans le cache
             // add_from_reader lance l'ingestion en arrière-plan et retourne dès que
@@ -138,6 +146,7 @@ impl NodeLogic for FlacCacheSinkLogic {
             // Le cache skip automatiquement le header FLAC (512 octets) pour calculer le pk
             // à partir du contenu audio, évitant les collisions entre morceaux au même format
             let collection_ref = self.collection.as_deref();
+            tracing::debug!("FlacCacheSink: Starting cache ingestion and pump in parallel");
             let cache_future = self.cache.add_from_reader(
                 None,
                 flac_stream,
@@ -156,13 +165,15 @@ impl NodeLogic for FlacCacheSinkLogic {
             );
 
             // Attendre les deux tâches en parallèle
+            tracing::debug!("FlacCacheSink: Waiting for cache and pump to complete");
             let (cache_result, pump_result) = tokio::join!(cache_future, pump_future);
 
+            tracing::debug!("FlacCacheSink: tokio::join! completed, checking results");
             let pk = cache_result.map_err(|e| {
                 AudioError::ProcessingError(format!("Failed to add to cache: {}", e))
             })?;
 
-            tracing::debug!("Track added to cache with pk {}, prebuffer complete", pk);
+            tracing::debug!("FlacCacheSink: Track added to cache with pk {}, prebuffer complete", pk);
 
             let (_chunks, _samples, _duration_sec, stop_reason) = pump_result?;