♻️ improve playlist reattachment and enhance OpenHome state logging

- Skip renderer queue clear when rebinding to same container, triggering gentle refresh instead
- Add detailed tracing for STOP commands across renderers and OpenHome clients  
- Improve `playback_state()` error handling with fallback to Transitioning for empty states
- Log queue state (length, current index/track ID) in `play_next`
- Add caller location tracing to OpenHome transport actions (`seek_id`, `delete_all`)
- Enhance IdArrayResponse logging with raw XML children for debugging
- Support both `<Value>` and <State> elements in Transport State responses
This commit is contained in:
2026-03-31 15:43:12 +02:00
parent c0d1e1a3d5
commit 494cc3b8e1
6 changed files with 111 additions and 14 deletions

BIN
.DS_Store vendored

Binary file not shown.

View File

@@ -1157,6 +1157,46 @@ impl ControlPoint {
container_id: &str, container_id: &str,
auto_play: bool, auto_play: bool,
) -> Result<(), ControlPointError> { ) -> Result<(), ControlPointError> {
// If already bound to the same container on the same server, don't clear the
// renderer queue — that would interrupt active playback. Instead, just trigger
// a gentle refresh (which uses LCS and preserves the currently playing track).
let renderer = self.music_renderer_by_id(renderer_id).ok_or_else(|| {
ControlPointError::ControlPoint(format!("Renderer {} not found", renderer_id.0))
})?;
let already_bound = renderer
.get_playlist_binding()
.map(|b| b.server_id == *server_id && b.container_id == container_id)
.unwrap_or(false);
if already_bound {
debug!(
renderer = renderer_id.0.as_str(),
server = server_id.0.as_str(),
container = container_id,
auto_play,
"Re-attach to same container: skipping clear, triggering gentle refresh"
);
let mut binding = renderer.get_playlist_binding().unwrap();
binding.pending_refresh = true;
binding.auto_play_on_refresh = auto_play;
renderer.set_playlist_binding(Some(binding));
let mut auto_start_cb = |rid: &DeviceId| self.play_current_from_queue(rid);
let callback: Option<&mut dyn FnMut(&DeviceId) -> Result<(), ControlPointError>> =
if auto_play {
Some(&mut auto_start_cb)
} else {
None
};
return refresh_attached_queue_for(
&self.registry,
renderer_id,
&self.event_bus,
callback,
);
}
// CRITICAL: When attaching a new playlist to a renderer, we must UNCONDITIONALLY // CRITICAL: When attaching a new playlist to a renderer, we must UNCONDITIONALLY
// clear the RENDERER queue first (but NOT the local queue cache, which will be // clear the RENDERER queue first (but NOT the local queue cache, which will be
// replaced by refresh_attached_queue_for() using replace_entire_playlist()). // replaced by refresh_attached_queue_for() using replace_entire_playlist()).
@@ -1170,10 +1210,6 @@ impl ControlPoint {
"Attaching new playlist: clearing renderer queue" "Attaching new playlist: clearing renderer queue"
); );
// Prepare the renderer for the new playlist (backend-agnostic)
let renderer = self.music_renderer_by_id(renderer_id).ok_or_else(|| {
ControlPointError::ControlPoint(format!("Renderer {} not found", renderer_id.0))
})?;
renderer.clear_for_playlist_attach()?; renderer.clear_for_playlist_attach()?;
// Sync backend state to local cache (backend-agnostic) // Sync backend state to local cache (backend-agnostic)

View File

@@ -849,6 +849,10 @@ impl MusicRenderer {
} }
// Then stop playback (ignore errors if already stopped) // Then stop playback (ignore errors if already stopped)
tracing::trace!(
renderer = self.id().0.as_str(),
"STOP command via clear_for_playlist_attach"
);
backend.stop().or_else(|err| { backend.stop().or_else(|err| {
warn!( warn!(
renderer = self.id().0.as_str(), renderer = self.id().0.as_str(),
@@ -964,6 +968,7 @@ impl MusicRenderer {
} }
/// Transport control: stop /// Transport control: stop
#[track_caller]
pub fn stop(&self) -> Result<(), ControlPointError> { pub fn stop(&self) -> Result<(), ControlPointError> {
// Reset the has_played flag when stopping playback. // Reset the has_played flag when stopping playback.
// This ensures that if we start a new track, the flag will be false // This ensures that if we start a new track, the flag will be false
@@ -971,6 +976,12 @@ impl MusicRenderer {
// transient STOPPED states during track initialization. // transient STOPPED states during track initialization.
self.clear_has_played_flag(); self.clear_has_played_flag();
let caller = std::panic::Location::caller();
tracing::trace!(
renderer = self.info.friendly_name(),
caller = %caller,
"STOP command sent to renderer"
);
self.lock_backend_for("stop").stop() self.lock_backend_for("stop").stop()
} }

View File

@@ -342,13 +342,25 @@ impl VolumeControl for OpenHomeRenderer {
impl PlaybackStatus for OpenHomeRenderer { impl PlaybackStatus for OpenHomeRenderer {
fn playback_state(&self) -> Result<PlaybackState, ControlPointError> { fn playback_state(&self) -> Result<PlaybackState, ControlPointError> {
let client = self.playlist_client_for("playback_state")?; let client = self.playlist_client_for("playback_state")?;
let raw = client.transport_state()?; let raw = client.transport_state().map_err(|err| {
tracing::warn!(
error = %err,
"OpenHome transport_state() failed — state change detection disabled"
);
err
})?;
let mapped = if raw.is_empty() {
tracing::trace!("OpenHome TransportState: empty (device initializing)");
PlaybackState::Transitioning
} else {
let mapped = map_openhome_state(&raw); let mapped = map_openhome_state(&raw);
tracing::trace!( tracing::trace!(
raw_state = raw.as_str(), raw_state = raw.as_str(),
mapped_state = ?mapped, mapped_state = ?mapped,
"OpenHome TransportState" "OpenHome TransportState"
); );
mapped
};
Ok(mapped) Ok(mapped)
} }
} }
@@ -550,9 +562,13 @@ impl QueueTransportControl for OpenHomeRenderer {
.map_err(|_| ControlPointError::QueueError("Queue mutex poisoned".into()))?; .map_err(|_| ControlPointError::QueueError("Queue mutex poisoned".into()))?;
let len = queue.len().unwrap_or(0); let len = queue.len().unwrap_or(0);
let current = queue.current_index().ok().flatten(); let current = queue.current_index().ok().flatten();
let current_track_id = queue.current_track().ok().flatten();
let all_ids = queue.track_ids().ok().unwrap_or_default();
tracing::trace!( tracing::trace!(
queue_len = len, queue_len = len,
current_index = ?current, current_index = ?current,
current_track_id = ?current_track_id,
all_track_ids = ?all_ids,
"OpenHome play_next: advancing queue" "OpenHome play_next: advancing queue"
); );
if !queue.advance()? { if !queue.advance()? {

View File

@@ -869,6 +869,13 @@ impl QueueBackend for OpenHomeQueue {
// Cache miss or expired - fetch from service (keep lock held to prevent concurrent calls) // Cache miss or expired - fetch from service (keep lock held to prevent concurrent calls)
let ids = self.playlist_client.id_array()?; let ids = self.playlist_client.id_array()?;
tracing::trace!(
renderer = self.renderer_id.0.as_str(),
ids_count = ids.len(),
ids = ?ids,
"track_ids: cache miss, fetched from Pizzicato"
);
// Update cache before releasing lock // Update cache before releasing lock
cache.set(ids.clone()); cache.set(ids.clone());
@@ -1008,6 +1015,10 @@ impl QueueBackend for OpenHomeQueue {
self.playlist_client.seek_id(track_id)?; self.playlist_client.seek_id(track_id)?;
} else { } else {
self.ensure_playlist_source_selected()?; self.ensure_playlist_source_selected()?;
tracing::trace!(
renderer = self.renderer_id.0.as_str(),
"STOP command via set_index(None) on OpenHome playlist"
);
self.playlist_client.stop()?; self.playlist_client.stop()?;
} }
// Invalidate caches (seek_id/stop modifies playlist state and current track) // Invalidate caches (seek_id/stop modifies playlist state and current track)

View File

@@ -2,8 +2,9 @@ use crate::errors::ControlPointError;
use crate::model::TrackMetadata; use crate::model::TrackMetadata;
use crate::soap_client::{ use crate::soap_client::{
decode_base64, ensure_success_with_envelope as ensure_success, extract_child_text, decode_base64, ensure_success_with_envelope as ensure_success, extract_child_text,
extract_child_text_any, extract_child_text_local, extract_child_text_optional, extract_child_text_allow_empty, extract_child_text_any, extract_child_text_local,
extract_child_text_optional_local, find_child_with_suffix, handle_action_response, extract_child_text_optional, extract_child_text_optional_local, find_child_with_suffix,
handle_action_response,
invoke_upnp_action, parse_bool, parse_visible_flag, invoke_upnp_action, parse_bool, parse_visible_flag,
}; };
use anyhow::{Result, anyhow}; use anyhow::{Result, anyhow};
@@ -270,7 +271,8 @@ impl OhPlaylistClient {
ControlPointError::UpnpMissingReturnValue("TransportStateResponse".to_string()) ControlPointError::UpnpMissingReturnValue("TransportStateResponse".to_string())
})?; })?;
let state = extract_child_text_any(response, &["State", "Value"])?; // upmpdcli returns <Value>, other implementations may use <State>
let state = extract_child_text_any(response, &["Value", "State"])?;
Ok(state) Ok(state)
} }
@@ -331,7 +333,10 @@ impl OhPlaylistClient {
handle_action_response("SeekSecondAbsolute", &call_result) handle_action_response("SeekSecondAbsolute", &call_result)
} }
#[track_caller]
pub fn delete_id(&self, id: u32) -> Result<(), ControlPointError> { pub fn delete_id(&self, id: u32) -> Result<(), ControlPointError> {
let caller = std::panic::Location::caller();
tracing::trace!(control_url = self.control_url.as_str(), id, caller = %caller, "OpenHome DeleteId");
let id_str = id.to_string(); let id_str = id.to_string();
let args = [("Value", id_str.as_str())]; let args = [("Value", id_str.as_str())];
@@ -379,7 +384,10 @@ impl OhPlaylistClient {
} }
} }
#[track_caller]
pub fn delete_all(&self) -> Result<(), ControlPointError> { pub fn delete_all(&self) -> Result<(), ControlPointError> {
let caller = std::panic::Location::caller();
tracing::trace!(control_url = self.control_url.as_str(), caller = %caller, "OpenHome DeleteAll");
let call_result = let call_result =
invoke_upnp_action(&self.control_url, &self.service_type, "DeleteAll", &[])?; invoke_upnp_action(&self.control_url, &self.service_type, "DeleteAll", &[])?;
handle_action_response("DeleteAll", &call_result) handle_action_response("DeleteAll", &call_result)
@@ -409,6 +417,21 @@ impl OhPlaylistClient {
let response = find_child_with_suffix(&envelope.body.content, "IdArrayResponse") let response = find_child_with_suffix(&envelope.body.content, "IdArrayResponse")
.ok_or_else(|| ControlPointError::upnp_missing_return_value("IdArrayResponse"))?; .ok_or_else(|| ControlPointError::upnp_missing_return_value("IdArrayResponse"))?;
// Log the raw IdArrayResponse XML for debugging
{
let raw_children: Vec<String> = response.children.iter()
.map(|n: &xmltree::XMLNode| match n {
xmltree::XMLNode::Element(e) => format!("{}={:?}", e.name, e.get_text()),
_ => String::new(),
})
.filter(|s| !s.is_empty())
.collect();
tracing::trace!(
children = ?raw_children,
"id_array: IdArrayResponse children"
);
}
// Try to extract the array element. If missing, assume empty playlist. // Try to extract the array element. If missing, assume empty playlist.
let array_text = match extract_child_text_any(response, &["Array", "IdArray", "Value"]) { let array_text = match extract_child_text_any(response, &["Array", "IdArray", "Value"]) {
Ok(text) => text, Ok(text) => text,