diff --git a/.DS_Store b/.DS_Store index b3752861..eb344ba7 100644 Binary files a/.DS_Store and b/.DS_Store differ diff --git a/pmocontrol/src/control_point.rs b/pmocontrol/src/control_point.rs index 998fe91a..6769bac8 100644 --- a/pmocontrol/src/control_point.rs +++ b/pmocontrol/src/control_point.rs @@ -892,7 +892,13 @@ impl ControlPoint { })?; // Check if queue is empty before trying to play next - if renderer.len()? == 0 { + let queue_len = renderer.len()?; + tracing::trace!( + renderer = renderer_id.0.as_str(), + queue_len, + "play_next_from_queue: checking queue length" + ); + if queue_len == 0 { debug!( renderer = renderer_id.0.as_str(), "play_next_from_queue: queue is empty" @@ -1510,6 +1516,11 @@ fn refresh_attached_queue_for( // Reset the pending_refresh flag and consume auto_play renderer.reset_pending_refresh(); let auto_play = renderer.consume_auto_play(); + tracing::trace!( + renderer = renderer_id.0.as_str(), + auto_play, + "refresh_attached_queue_for: auto_play flag consumed" + ); // Step 2: Get server from registry let music_server = { diff --git a/pmocontrol/src/music_renderer/musicrenderer.rs b/pmocontrol/src/music_renderer/musicrenderer.rs index a428b2bb..f91c8fb0 100644 --- a/pmocontrol/src/music_renderer/musicrenderer.rs +++ b/pmocontrol/src/music_renderer/musicrenderer.rs @@ -552,6 +552,12 @@ impl MusicRenderer { // Emit event for all state changes including Transitioning if changed { + tracing::trace!( + renderer = self.info.friendly_name(), + prev_state = ?watched.state, + new_state = ?raw_state, + "Playback state changed" + ); let state_clone = raw_state.clone(); drop(watched); self.emit_event(RendererEvent::StateChanged { @@ -631,6 +637,15 @@ impl MusicRenderer { fn handle_state_change(&self, state: &PlaybackState) { match state { PlaybackState::Stopped => { + { + let s = self.state.lock().unwrap(); + tracing::trace!( + renderer = self.info.friendly_name(), + has_played = s.has_played_since_track_start, + playback_source = ?s.playback_source, + "STOPPED detected — evaluating auto-advance" + ); + } // Check if user requested stop (via Stop button in UI) if self.check_and_clear_user_stop_requested() { debug!( @@ -695,6 +710,15 @@ impl MusicRenderer { // Mark that we have seen a PLAYING state - auto-advance is now allowed self.set_has_played_flag(); } + PlaybackState::Transitioning => { + let s = self.state.lock().unwrap(); + tracing::trace!( + renderer = self.info.friendly_name(), + has_played = s.has_played_since_track_start, + playback_source = ?s.playback_source, + "TRANSITIONING detected" + ); + } _ => {} } } diff --git a/pmocontrol/src/music_renderer/openhome_renderer.rs b/pmocontrol/src/music_renderer/openhome_renderer.rs index 47002404..f046dcd4 100644 --- a/pmocontrol/src/music_renderer/openhome_renderer.rs +++ b/pmocontrol/src/music_renderer/openhome_renderer.rs @@ -342,8 +342,14 @@ impl VolumeControl for OpenHomeRenderer { impl PlaybackStatus for OpenHomeRenderer { fn playback_state(&self) -> Result { let client = self.playlist_client_for("playback_state")?; - let state = client.transport_state()?; - Ok(map_openhome_state(&state)) + let raw = client.transport_state()?; + let mapped = map_openhome_state(&raw); + tracing::trace!( + raw_state = raw.as_str(), + mapped_state = ?mapped, + "OpenHome TransportState" + ); + Ok(mapped) } } @@ -542,7 +548,19 @@ impl QueueTransportControl for OpenHomeRenderer { .queue .lock() .map_err(|_| ControlPointError::QueueError("Queue mutex poisoned".into()))?; + let len = queue.len().unwrap_or(0); + let current = queue.current_index().ok().flatten(); + tracing::trace!( + queue_len = len, + current_index = ?current, + "OpenHome play_next: advancing queue" + ); if !queue.advance()? { + tracing::trace!( + queue_len = len, + current_index = ?current, + "OpenHome play_next: advance() returned false — no next track" + ); return Err(ControlPointError::QueueError("No next track".into())); } } diff --git a/pmocontrol/src/queue/openhome.rs b/pmocontrol/src/queue/openhome.rs index c37b0be4..9b0d5eca 100644 --- a/pmocontrol/src/queue/openhome.rs +++ b/pmocontrol/src/queue/openhome.rs @@ -66,6 +66,50 @@ impl TrackIdsCache { } } +/// Cache for ReadList results to avoid redundant SOAP calls within a short window. +/// Key: sorted list of requested IDs. TTL: 500ms. +#[derive(Debug)] +struct ReadListCache { + ids: Option>, + entries: Option>, + last_update: Option, +} + +impl ReadListCache { + fn new() -> Self { + Self { + ids: None, + entries: None, + last_update: None, + } + } + + fn get(&self, id_list: &[u32]) -> Option> { + if let (Some(cached_ids), Some(entries), Some(last_update)) = + (&self.ids, &self.entries, self.last_update) + { + if let Ok(elapsed) = SystemTime::now().duration_since(last_update) { + if elapsed.as_millis() < 500 && cached_ids.as_slice() == id_list { + return Some(entries.clone()); + } + } + } + None + } + + fn set(&mut self, ids: Vec, entries: Vec) { + self.ids = Some(ids); + self.entries = Some(entries); + self.last_update = Some(SystemTime::now()); + } + + fn invalidate(&mut self) { + self.ids = None; + self.entries = None; + self.last_update = None; + } +} + /// Cache for current track ID to avoid redundant Id SOAP calls #[derive(Debug)] struct CurrentTrackIdCache { @@ -130,6 +174,8 @@ pub struct OpenHomeQueue { track_ids_cache: Arc>, /// Cache for current track ID to avoid redundant Id SOAP calls current_track_id_cache: Arc>, + /// Cache for ReadList results (TTL 500ms) to avoid redundant SOAP calls + read_list_cache: Arc>, } impl OpenHomeQueue { @@ -147,6 +193,7 @@ impl OpenHomeQueue { metadata_cache: Mutex::new(HashMap::new()), track_ids_cache: Arc::new(Mutex::new(TrackIdsCache::new())), current_track_id_cache: Arc::new(Mutex::new(CurrentTrackIdCache::new())), + read_list_cache: Arc::new(Mutex::new(ReadListCache::new())), } } @@ -406,6 +453,7 @@ impl OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -584,6 +632,7 @@ impl OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -686,6 +735,7 @@ impl OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -890,13 +940,28 @@ impl QueueBackend for OpenHomeQueue { }); } - // Read metadata for all tracks (batched) - // playback_item_from_entry() will prioritize cached metadata over entry metadata + // Read metadata for all tracks (batched), with 500ms cache to avoid + // redundant SOAP calls during sync_queue (which calls queue_snapshot twice). const MAX_BATCH: usize = 64; let mut entries = Vec::with_capacity(ids.len()); for chunk in ids.chunks(MAX_BATCH) { + if let Some(cached) = self.read_list_cache.lock().unwrap().get(chunk) { + trace!( + renderer = self.renderer_id.0.as_str(), + "ReadList cache hit for {} IDs", + chunk.len() + ); + entries.extend(cached); + continue; + } match self.playlist_client.read_list(chunk) { - Ok(mut batch) => entries.append(&mut batch), + Ok(batch) => { + self.read_list_cache + .lock() + .unwrap() + .set(chunk.to_vec(), batch.clone()); + entries.extend(batch); + } Err(err) => { // If batch fails, try one by one if chunk.len() > 1 { @@ -947,6 +1012,7 @@ impl QueueBackend for OpenHomeQueue { } // Invalidate caches (seek_id/stop modifies playlist state and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); Ok(()) } @@ -972,6 +1038,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate caches after delete_all (clears queue and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); if items.is_empty() { @@ -994,6 +1061,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate cache after insertions self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -1005,6 +1073,7 @@ impl QueueBackend for OpenHomeQueue { self.metadata_cache.lock().unwrap().clear(); // Invalidate caches after delete_all (clears queue and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); return Ok(()); } @@ -1053,6 +1122,15 @@ impl QueueBackend for OpenHomeQueue { .position(|item| item.didl_id == playing_didl_id) }); + tracing::trace!( + renderer = self.renderer_id.0.as_str(), + playing_uri = playing_uri.as_str(), + playing_didl_id = ?playing_didl_id, + pivot_found = new_playing_idx.is_some(), + desired_uris = ?items.iter().map(|i| i.uri.as_str()).collect::>(), + "sync_queue: pivot search result" + ); + if let Some(pivot_idx) = new_playing_idx { // CASE 2: Currently playing item IS in the new playlist // Use gentle double-LCS strategy: preserve the pivot and sync before/after separately @@ -1142,6 +1220,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -1187,6 +1266,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate cache after playlist modifications (except ReplaceAll which already does it) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -1199,6 +1279,7 @@ impl QueueBackend for OpenHomeQueue { self.playlist_client.delete_all()?; // Invalidate caches after clearing playlist (clears queue and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); Ok(()) }