Merge PR #127: Sonos queue verification, cast double-download fix, stutter instrumentation
android / Build + lint + test (push) Successful in 4m16s
release / Build signed APK (tag releases only) (push) Successful in 5m25s
release / Build + push container image (push) Successful in 1m16s
release / Verify release artifacts (tag releases only) (push) Successful in 1s

This commit was merged in pull request #127.
This commit is contained in:
2026-08-18 10:50:10 -04:00
13 changed files with 1183 additions and 256 deletions
@@ -18,6 +18,7 @@ import com.fabledsword.minstrel.connectivity.NetworkStatusController
import com.fabledsword.minstrel.di.ApplicationScope
import com.fabledsword.minstrel.player.PlayerController
import com.fabledsword.minstrel.player.RemotePlayerState
import com.fabledsword.minstrel.player.TransportObservation
import com.fabledsword.minstrel.player.output.OutputPickerController
import com.fabledsword.minstrel.player.output.OutputRoute
import dagger.hilt.android.qualifiers.ApplicationContext
@@ -103,6 +104,7 @@ class DiagnosticsReporter @Inject constructor(
launch { collectUpnpDrops() }
launch { collectPlayerState() }
launch { collectTrackChanges() }
launch { collectTransportFlap() }
launch { collectRoutes() }
launch { heartbeatLoop() }
}
@@ -191,6 +193,67 @@ class DiagnosticsReporter @Inject constructor(
}
}
/**
* Catch the renderer rapidly leaving and re-entering PLAYING.
*
* The operator reports the Sonos "play pause play pause, like someone
* pressing it every half second", usually as a track starts, cleared by a
* manual pause or skip. Nothing here could see that: `player_state`
* carries source/loading/error but not playing, `track_change` needs the
* index to move, and the heartbeat samples once per 45s. The symptom fell
* through every existing collector, which is why it has only ever been
* described and never measured.
*
* Records every raw transport change (cheap — steady playback produces
* a couple per track) and, when they come in a burst, one summary event
* carrying the whole sequence. The summary is the useful artefact: it
* pairs the renderer's states with local-vs-Sonos track and position, so
* an episode says whether the app and the renderer disagreed about which
* track was playing, or agreed while the renderer rebuffered.
*
* See [TransportObservation] on the 1 Hz sampling limit.
*/
private suspend fun collectTransportFlap() {
val detector = TransportFlapDetector()
playerController.transportEvents.collect { obs ->
record("upnp_sync", buildJsonObject {
put("event", "transport")
put("state", obs.state)
put("status_ok", obs.statusOk)
put("sonos_track", obs.trackNumber)
put("sonos_pos_ms", obs.positionMs)
put("play_intent", obs.playIntent)
})
detector.onChange(obs)?.let { recordFlapSummary(it) }
}
}
private suspend fun recordFlapSummary(recent: List<TransportObservation>) {
val ui = playerController.uiState.value
val casting = outputPicker.routesState.value.current.protocol !=
OutputRoute.Protocol.SYSTEM
val spanMs = recent.last().atElapsedMs - recent.first().atElapsedMs
record("upnp_sync", buildJsonObject {
put("event", "transport_flap")
put("changes", recent.size)
put("window_ms", spanMs)
// The sequence itself, e.g. "PLAYING>TRANSITIONING>STOPPED>PLAYING".
// Whether STOPPED appears at all is the first question to ask of a
// captured episode.
put("sequence", recent.joinToString(">") { it.state })
put("sonos_positions_ms", recent.joinToString(",") { it.positionMs.toString() })
put("sonos_tracks", recent.joinToString(",") { it.trackNumber.toString() })
put("local_index", ui.queueIndex)
put("local_track_id", ui.currentTrack?.id ?: "")
put("local_pos_ms", ui.positionMs)
putSonos(this, casting)
put("upnp_loading", ui.isUpnpLoading)
put("server_health", networkStatus.state.value.name)
put("route", outputPicker.routesState.value.current.name)
addPowerFields(this)
})
}
private suspend fun collectRoutes() {
// 'playback' — route changes happen for all outputs. This only ever
// logs the ACTIVE route (routesState.current), so no "connected" flag.
@@ -0,0 +1,75 @@
package com.fabledsword.minstrel.diagnostics
import com.fabledsword.minstrel.player.TransportObservation
/**
* Decides when a run of renderer transport changes is a *flap* — the renderer
* repeatedly failing to settle — rather than an ordinary track transition.
*
* The operator reports the Sonos "play pause play pause, like someone pressing
* it every half second", usually as a track starts. No diagnostic event could
* see it, so it has been described several times and measured never. This is
* the rule that decides when an episode is worth writing down.
*
* Pure decision state, like [com.fabledsword.minstrel.player.RemoteStallWatchdog]:
* the caller owns the flow and the recording, this only answers "is this an
* episode, and which readings make it up". Keeps the windowing and the
* one-episode-one-summary rule testable without a renderer or a clock.
*/
class TransportFlapDetector(
private val windowMs: Long = FLAP_WINDOW_MS,
private val minChanges: Int = FLAP_MIN_CHANGES,
private val summaryCooldownMs: Long = FLAP_SUMMARY_COOLDOWN_MS,
) {
private val recent = ArrayDeque<TransportObservation>()
private var lastSummaryAtMs: Long? = null
/**
* Feed one transport change. Returns the readings making up an episode
* worth recording, or null when there is nothing to say.
*
* The returned list is a copy: the caller may hold it while more readings
* arrive.
*/
fun onChange(observation: TransportObservation): List<TransportObservation>? {
recent.addLast(observation)
dropReadingsOlderThan(observation.atElapsedMs)
if (!isEpisode(observation.atElapsedMs)) return null
lastSummaryAtMs = observation.atElapsedMs
return recent.toList()
}
private fun dropReadingsOlderThan(nowMs: Long) {
while (recent.isNotEmpty() && nowMs - recent.first().atElapsedMs > windowMs) {
recent.removeFirst()
}
}
/**
* Enough changes packed together, and far enough from the last thing we
* wrote down. The cooldown is what keeps one episode to one summary: a
* sustained fault produces a change every poll, and a summary per reading
* would bury the per-change events underneath them.
*/
private fun isEpisode(nowMs: Long): Boolean {
val since = lastSummaryAtMs
val cooled = since == null || nowMs - since >= summaryCooldownMs
return recent.size >= minChanges && cooled
}
/** Forget everything — call when the route changes or casting ends. */
fun reset() {
recent.clear()
lastSummaryAtMs = null
}
companion object {
// Readings arrive at the 1 Hz poll cadence, and a normal track
// transition is 2-3 changes (PLAYING -> TRANSITIONING -> PLAYING).
// Four inside six seconds is not a track change, and it is not a
// person at the Sonos app either; it is the renderer not settling.
const val FLAP_WINDOW_MS = 6_000L
const val FLAP_MIN_CHANGES = 4
const val FLAP_SUMMARY_COOLDOWN_MS = 60_000L
}
}
@@ -14,6 +14,7 @@ import com.fabledsword.minstrel.connectivity.NetworkStatusController
import com.fabledsword.minstrel.connectivity.ServerHealth
import com.fabledsword.minstrel.player.output.ActiveUpnp
import com.fabledsword.minstrel.player.output.ActiveUpnpHolder
import com.fabledsword.minstrel.player.output.upnp.PositionInfo
import com.fabledsword.minstrel.player.output.upnp.SoapFaultException
import com.fabledsword.minstrel.player.output.upnp.TransportInfo
import com.fabledsword.minstrel.player.output.upnp.TransportState
@@ -48,12 +49,12 @@ import timber.log.Timber
*
* Drop heuristic: the 1 Hz poll loop is the *sole* arbiter of route
* liveness -- [RemotePlayerState.recordPollFailure]'s rolling threshold
* (DROP_THRESHOLD consecutive failures) fires [onDrop]. A failed transport
* (DROP_THRESHOLD consecutive failures) fires [RemoteEvents.onDrop]. A failed transport
* command (play/pause/seek/next) does NOT drop on its own: a locked phone's
* WiFi power-save can stall a single command's socket I/O for a second or
* two while the renderer is perfectly reachable, so commands retry on
* transient IO failure and otherwise defer to the poll loop. The factory
* wraps the [onDrop] callback into a SharedFlow consumed by the NowPlaying
* wraps that callback into a SharedFlow consumed by the NowPlaying
* surface as a snackbar.
*
* Queue mode: OutputPickerController loads the full queue into Sonos's
@@ -71,10 +72,29 @@ class MinstrelForwardingPlayer(
private val remoteState: RemotePlayerState,
private val castNetworkLock: CastNetworkLock,
private val networkStatus: NetworkStatusController,
private val onDrop: (routeName: String) -> Unit,
private val onStalled: (trackId: String) -> Unit = {},
private val events: RemoteEvents = RemoteEvents(),
) : ForwardingPlayer(delegate) {
/**
* The ways remote playback reports trouble outward. Grouped rather than
* passed as three more constructor lambdas: they share a lifetime, they
* all end up as flows on [PlayerFactory], and the list grows every time
* the renderer finds a new way to disappoint us.
*/
data class RemoteEvents(
/** A route stopped answering and playback fell back to the phone. */
val onDrop: (routeName: String) -> Unit = {},
/** A track could not be got playing again; surfaces to the user. */
val onStalled: (trackId: String) -> Unit = {},
/** The renderer's queue is short of ours and needs rebuilding. */
val onQueueTruncated: () -> Unit = {},
/**
* A raw poll reading, emitted only when it differs from the previous
* one. Diagnostics-only; see [TransportObservation].
*/
val onTransport: (TransportObservation) -> Unit = {},
)
private val scope = CoroutineScope(SupervisorJob() + Dispatchers.IO)
private val handler = Handler(delegate.applicationLooper)
private var pollJob: Job? = null
@@ -97,6 +117,16 @@ class MinstrelForwardingPlayer(
// visibly jumps backwards immediately after a drag, then forwards again.
@Volatile private var lastSeekIssuedAtMs: Long = 0L
// Last-read renderer queue length + when we read it. See [queueStateFor]:
// a stopped renderer is polled once a second and its queue does not change
// by itself, so re-asking every tick is pure round-trips.
@Volatile private var cachedNrTracks: Int = 0
@Volatile private var lastMediaInfoAtMs: Long = 0L
// Previous raw transport reading, so [TransportObservation]s are emitted
// on change rather than once a second forever. Null until the first poll.
@Volatile private var lastObservedTransport: Pair<TransportState, Boolean>? = null
// Wake channel for the poll loop. requestImmediatePoll() trySend's a Unit;
// pollLoop's select{} races the delay against this channel so the next
// pollOnce can fire immediately instead of waiting up to POLL_INTERVAL_MS.
@@ -488,17 +518,35 @@ class MinstrelForwardingPlayer(
// without this the radio power-saves on a locked screen and the
// poll below starves -- see [CastNetworkLock].
castNetworkLock.acquire()
// Pause the wrapped ExoPlayer so we are not playing local audio
// simultaneously with the remote renderer. handler.post targets the
// application looper, so this runs on the same thread that processes
// our override calls -- no race with the pause() override branching
// to SOAP (holder.active is already non-null by the time this post
// fires, but delegate.pause() bypasses the override entirely).
handler.post { delegate.pause() }
// STOP the wrapped ExoPlayer -- not pause. pause() is only
// playWhenReady=false: ExoPlayer's LoadControl keeps loading, so a
// paused-but-prepared player goes on downloading the current track
// (~50s of buffer). During a cast that means the phone pulls the
// same file the renderer is streaming, over the same WiFi, and
// re-arms on every track change via syncLocalCursorToRemote's
// seekTo. At FLAC bitrates that is a second full-rate download
// competing with the speaker for air, starting exactly when a new
// track does. stop() ends the loading; Media3 keeps the media
// items, the current index and the position, so cursor sync and
// the handoff back are unaffected, and getPlaybackState() already
// reports STATE_READY while remote so no external reader sees IDLE.
//
// handler.post targets the application looper, so this runs on the
// same thread that processes our override calls -- no race with the
// pause() override branching to SOAP (holder.active is already
// non-null by the time this post fires, but delegate.stop()
// bypasses the override entirely).
handler.post { delegate.stop() }
pollJob = scope.launch { pollLoop(active) }
} else {
castNetworkLock.release()
remoteState.reset()
lastObservedTransport = null
// The delegate was stopped for the cast, so it is IDLE and would
// ignore a play(). Re-prepare it for local playback. Safe when the
// queue is empty, and it does not start playback on its own --
// playWhenReady is still false until something calls play().
handler.post { delegate.prepare() }
// The next cast starts with a clean attempt budget; a stall on the
// route we just left says nothing about the next one.
stallWatchdog.reset()
@@ -516,7 +564,7 @@ class MinstrelForwardingPlayer(
} else if (remoteState.recordPollFailure()) {
if (networkStatus.state.value == ServerHealth.Healthy) {
Timber.w("UPnP drop threshold tripped for %s", active.routeName)
handler.post { onDrop(active.routeName) }
handler.post { events.onDrop(active.routeName) }
return
}
networkDropSuppressed = suppressDropForNetwork(active, networkDropSuppressed)
@@ -594,6 +642,7 @@ class MinstrelForwardingPlayer(
}
TransportState.TRANSITIONING, TransportState.UNKNOWN -> Unit
}
observeTransport(transport, info)
checkForStall(active, info.trackUri, transport)
notifyRemoteStateChanged()
}
@@ -613,12 +662,15 @@ class MinstrelForwardingPlayer(
transport: TransportInfo,
) {
val decision = stallWatchdog.onPoll(
trackUri = trackUri,
state = transport.state,
statusOk = transport.statusOk,
playIntent = remoteState.lastPlayIntent,
positionMs = remoteState.positionMs,
nowMs = SystemClock.elapsedRealtime(),
RemoteStallWatchdog.Poll(
trackUri = trackUri,
state = transport.state,
statusOk = transport.statusOk,
playIntent = remoteState.lastPlayIntent,
positionMs = remoteState.positionMs,
nowMs = SystemClock.elapsedRealtime(),
queue = queueStateFor(active, transport),
),
)
when (decision) {
is RemoteStallWatchdog.Decision.Resume -> {
@@ -638,6 +690,17 @@ class MinstrelForwardingPlayer(
Timber.w(it, "UPnP stall: resume attempt failed on %s", active.routeName)
}
}
is RemoteStallWatchdog.Decision.RepairQueue -> {
Timber.w(
"UPnP queue truncated on %s: renderer ended at its last track " +
"while %d local tracks remain; repair attempt %d",
active.routeName, delegate.mediaItemCount, decision.attempt,
)
// The renderer isn't broken -- it played everything it was
// given. Rebuilding the queue is the fix; the controller owns
// queue loading, so ask it rather than duplicating that here.
handler.post { events.onQueueTruncated() }
}
RemoteStallWatchdog.Decision.GiveUp -> {
Timber.w(
"UPnP stall on %s: giving up after repeated resume attempts",
@@ -645,12 +708,80 @@ class MinstrelForwardingPlayer(
)
// Tell the user and the admin inbox. Silence here would be the
// original bug: playback simply ends and nobody finds out.
trackIdFromStreamUri(trackUri)?.let { handler.post { onStalled(it) } }
trackIdFromStreamUri(trackUri)?.let { handler.post { events.onStalled(it) } }
}
RemoteStallWatchdog.Decision.None -> Unit
}
}
/**
* Publish this poll's raw transport reading if it differs from the last.
*
* Change-gated on purpose: steady playback is one reading repeated once a
* second, which is worth nothing and would fill the ring buffer. What is
* worth capturing is the renderer LEAVING a state — which during normal
* playback happens a couple of times per track, and during the fault the
* operator describes should happen repeatedly within a few seconds.
*/
private fun observeTransport(transport: TransportInfo, info: PositionInfo) {
val key = transport.state to transport.statusOk
if (key == lastObservedTransport) return
lastObservedTransport = key
events.onTransport(
TransportObservation(
state = transport.state.name,
statusOk = transport.statusOk,
trackNumber = info.track,
positionMs = info.relTimeMs,
playIntent = remoteState.lastPlayIntent,
atElapsedMs = SystemClock.elapsedRealtime(),
),
)
}
/**
* How the renderer's queue compares to ours, for [RemoteStallWatchdog].
*
* Only asked when the transport is actually stopped or reporting an error:
* while it plays, the answer changes nothing and GetMediaInfo would be a
* third SOAP round-trip every second. Even then the result is cached for
* [MEDIA_INFO_TTL_MS], because a stopped renderer gets polled once a
* second and its queue length does not change on its own.
*
* A renderer that reports NrTracks=0 is telling us nothing usable (some
* don't implement it) -- that reads as UNKNOWN, never as "empty queue",
* so an unhelpful renderer keeps the old resume-and-seek behaviour rather
* than being told its queue is broken.
*/
@Suppress("ReturnCount") // one early return per verdict reads better than nesting
private suspend fun queueStateFor(
active: ActiveUpnp,
transport: TransportInfo,
): RemoteStallWatchdog.QueueState {
val stalled = transport.state == TransportState.STOPPED || !transport.statusOk
if (!stalled) return RemoteStallWatchdog.QueueState.UNKNOWN
val now = SystemClock.elapsedRealtime()
if (now - lastMediaInfoAtMs > MEDIA_INFO_TTL_MS) {
lastMediaInfoAtMs = now
cachedNrTracks = runCatching { active.avTransport.getMediaInfo().nrTracks }
.onFailure { Timber.w(it, "UPnP GetMediaInfo failed on %s", active.routeName) }
.getOrDefault(0)
}
val nrTracks = cachedNrTracks
val rendererTrack = remoteState.trackNumber
if (nrTracks <= 0 || rendererTrack <= 0) return RemoteStallWatchdog.QueueState.UNKNOWN
if (rendererTrack < nrTracks) return RemoteStallWatchdog.QueueState.HAS_MORE
// On its last track. Whether that is a problem depends entirely on
// whether we have tracks it never received.
return if (delegate.mediaItemCount > nrTracks) {
RemoteStallWatchdog.QueueState.TRUNCATED
} else {
RemoteStallWatchdog.QueueState.COMPLETE
}
}
/**
* Align the paused local delegate cursor to the track the renderer is
* actually playing, so the un-overridden current-item getters
@@ -743,6 +874,10 @@ class MinstrelForwardingPlayer(
const val POLL_INTERVAL_MS = 1_000L
const val NON_PLAYING_CONFIRM = 2
const val SEEK_ACK_WINDOW_MS = 2_000L
// How long a GetMediaInfo queue-length reading stays good for. The
// watchdog needs three agreeing polls (~3s) before it acts, so one
// read comfortably covers a decision without asking every tick.
const val MEDIA_INFO_TTL_MS = 5_000L
// Safety upper bound on how long the polling tick will wait for
// Sonos to ack a user transport. The common case clears event-driven
// when Sonos's reported Track matches the wrapped player; this only
@@ -77,6 +77,13 @@ class PlayerController @Inject constructor(
* during UPnP playback shows "Disconnected from <name>" to the user.
*/
val dropEvents: SharedFlow<String> = playerFactory.dropEvents
/**
* Raw UPnP transport readings from [PlayerFactory.transportEvents], for
* the diagnostics reporter. Read-only tap — nothing in the playback path
* consumes it.
*/
val transportEvents: SharedFlow<TransportObservation> = playerFactory.transportEvents
private val sessionToken =
SessionToken(context, ComponentName(context, MinstrelPlayerService::class.java))
@@ -84,6 +84,29 @@ class PlayerFactory @Inject constructor(
)
val stallEvents: SharedFlow<String> = stallEventsInternal.asSharedFlow()
// Fires when the renderer is found to have reached the end of a queue
// shorter than ours -- i.e. part of the queue load never landed. The
// controller owns queue loading, so it collects this and rebuilds.
// Same one-is-enough buffering: repeated notices are the same problem.
private val queueRepairInternal = MutableSharedFlow<Unit>(
replay = 0,
extraBufferCapacity = 1,
onBufferOverflow = BufferOverflow.DROP_OLDEST,
)
val queueRepairEvents: SharedFlow<Unit> = queueRepairInternal.asSharedFlow()
// Raw renderer transport readings, change-gated. Unlike the flows above
// this one carries a SEQUENCE — the diagnostics flap detector needs
// several readings in a row to tell oscillation from a normal track
// transition — so it buffers more than one and drops oldest under
// pressure rather than collapsing to the latest.
private val transportInternal = MutableSharedFlow<TransportObservation>(
replay = 0,
extraBufferCapacity = TRANSPORT_EVENT_BUFFER,
onBufferOverflow = BufferOverflow.DROP_OLDEST,
)
val transportEvents: SharedFlow<TransportObservation> = transportInternal.asSharedFlow()
fun build(): Player {
val exo = buildExoPlayer()
return MinstrelForwardingPlayer(
@@ -92,8 +115,12 @@ class PlayerFactory @Inject constructor(
remoteState = remoteState,
castNetworkLock = CastNetworkLock(context),
networkStatus = serverHealth,
onDrop = { name -> emitDrop(name) },
onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) },
events = MinstrelForwardingPlayer.RemoteEvents(
onDrop = { name -> emitDrop(name) },
onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) },
onQueueTruncated = { queueRepairInternal.tryEmit(Unit) },
onTransport = { transportInternal.tryEmit(it) },
),
)
}
@@ -146,6 +173,12 @@ class PlayerFactory @Inject constructor(
.build(),
)
private companion object {
// Enough readings to hold a whole flap episode plus the normal
// transitions around it; the detector's window is only a few seconds.
const val TRANSPORT_EVENT_BUFFER = 32
}
private fun emitDrop(routeName: String) {
dropEventsInternal.tryEmit(routeName)
}
@@ -29,6 +29,23 @@ import com.fabledsword.minstrel.player.output.upnp.TransportState
* [RETRY_SPACING_MS]. A genuinely unplayable file must not become an
* infinite retry loop against the renderer.
*
* A stop is not always a fault, and not always the same fault. Three
* different things arrive here looking identical — the transport says
* STOPPED and we wanted to be playing:
*
* 1. The stream died mid-track. Re-play and seek back. ([Decision.Resume])
* 2. The renderer reached the end of a queue *shorter than ours*, because
* part of the load never landed. Nothing is broken; it is playing
* exactly what it was given. Repairing the queue is the fix, and
* re-playing the finished track is not. ([Decision.RepairQueue])
* 3. The renderer reached the end of the queue and so did we. Playback is
* simply over. ([Decision.None])
*
* Case 3 matters as much as the others: without [QueueState] every cast
* session would end with the watchdog retrying the last track three times
* and then reporting a `stalled` error for a listening session that
* finished perfectly normally.
*
* Pure decision state, no coroutines and no SOAP: the caller owns the poll
* loop and performs the transport calls, this only says what should happen.
* That keeps the awkward part — counting, keying and giving up — testable
@@ -36,6 +53,46 @@ import com.fabledsword.minstrel.player.output.upnp.TransportState
*/
class RemoteStallWatchdog {
/**
* What the renderer's queue looks like relative to ours, as of this poll.
* The caller derives it from GetMediaInfo's NrTracks against the local
* queue; it only needs to be accurate when the transport is not playing.
*/
enum class QueueState {
/**
* The renderer didn't report a usable count, or it is playing and the
* question is moot. Treated as "assume a real stall" — the old
* behaviour, which is right when we know nothing.
*/
UNKNOWN,
/** The renderer still has tracks after the current one. */
HAS_MORE,
/**
* The renderer is on its last track but our queue has tracks it never
* received — the load was truncated.
*/
TRUNCATED,
/** Renderer is on its last track and so are we: playback is over. */
COMPLETE,
}
/**
* One poll's worth of observation. Grouped into a type rather than passed
* as a long parameter list so adding a fact doesn't reshuffle call sites.
*/
data class Poll(
val trackUri: String,
val state: TransportState,
val statusOk: Boolean,
val playIntent: Boolean,
val positionMs: Long,
val nowMs: Long,
val queue: QueueState = QueueState.UNKNOWN,
)
sealed interface Decision {
/** Nothing to do. */
data object None : Decision
@@ -47,6 +104,14 @@ class RemoteStallWatchdog {
*/
data class Resume(val attempt: Int, val resumeAtMs: Long) : Decision
/**
* The renderer ran off the end of a queue we failed to fully load.
* The caller should append the tail it never got and resume at the
* next track — re-playing the current one would just replay a track
* the listener already heard.
*/
data class RepairQueue(val attempt: Int) : Decision
/** Attempts are exhausted. Report it and stop trying for this track. */
data object GiveUp : Decision
}
@@ -59,36 +124,22 @@ class RemoteStallWatchdog {
private var gaveUp: Boolean = false
/**
* Feed one poll result in, get the action out.
*
* @param trackUri the renderer's current track URI — identity for the
* per-track attempt budget, so moving to the next track forgives a
* previous one's failures.
* @param statusOk the transport's own status flag: false means the
* renderer is reporting an error rather than merely being stopped.
* @param playIntent the operator's last play/pause intent.
* @param nowMs a monotonic clock (SystemClock.elapsedRealtime), passed in
* so tests can drive time.
* Feed one poll result in, get the action out. See [Poll] for the inputs;
* `nowMs` is a monotonic clock (SystemClock.elapsedRealtime), passed in so
* tests can drive time.
*/
@Suppress("ReturnCount") // early returns per state are clearer than nesting
fun onPoll(
trackUri: String,
state: TransportState,
statusOk: Boolean,
playIntent: Boolean,
positionMs: Long,
nowMs: Long,
): Decision {
if (trackUri != trackKey) {
fun onPoll(poll: Poll): Decision {
if (poll.trackUri != trackKey) {
// New track: a fresh attempt budget, and no inherited stall state.
trackKey = trackUri
trackKey = poll.trackUri
resetStall()
attempts = 0
gaveUp = false
lastPlayingPositionMs = 0L
}
if (!playIntent) {
if (!poll.playIntent) {
// Stopped because we asked. Not a stall, and the next genuine one
// should start from a clean budget.
resetStall()
@@ -97,8 +148,8 @@ class RemoteStallWatchdog {
return Decision.None
}
if (state == TransportState.PLAYING && statusOk) {
lastPlayingPositionMs = positionMs
if (poll.state == TransportState.PLAYING && poll.statusOk) {
lastPlayingPositionMs = poll.positionMs
resetStall()
// A track that recovered and is playing again has earned back its
// budget; a later, unrelated stall on the same track should get
@@ -107,7 +158,7 @@ class RemoteStallWatchdog {
return Decision.None
}
val stalled = state == TransportState.STOPPED || !statusOk
val stalled = poll.state == TransportState.STOPPED || !poll.statusOk
if (!stalled) {
// PAUSED (someone else's doing) or TRANSITIONING/UNKNOWN (in
// flight). Neither is a stall; drop the streak so a mid-track
@@ -116,6 +167,14 @@ class RemoteStallWatchdog {
return Decision.None
}
// The queue simply ended. Not a fault, so it must not consume the
// attempt budget or raise an error — the listener heard everything
// they queued.
if (poll.queue == QueueState.COMPLETE) {
resetStall()
return Decision.None
}
stoppedStreak += 1
if (stoppedStreak < STALL_CONFIRM_POLLS) return Decision.None
if (gaveUp) return Decision.None
@@ -124,11 +183,15 @@ class RemoteStallWatchdog {
gaveUp = true
return Decision.GiveUp
}
if (attempts > 0 && nowMs - lastAttemptAtMs < RETRY_SPACING_MS) return Decision.None
if (attempts > 0 && poll.nowMs - lastAttemptAtMs < RETRY_SPACING_MS) return Decision.None
attempts += 1
lastAttemptAtMs = nowMs
return Decision.Resume(attempt = attempts, resumeAtMs = lastPlayingPositionMs)
lastAttemptAtMs = poll.nowMs
return if (poll.queue == QueueState.TRUNCATED) {
Decision.RepairQueue(attempt = attempts)
} else {
Decision.Resume(attempt = attempts, resumeAtMs = lastPlayingPositionMs)
}
}
/** Forget everything — call when the route changes or playback is torn down. */
@@ -0,0 +1,38 @@
package com.fabledsword.minstrel.player
/**
* One reading of what a UPnP renderer says it is doing, taken by the poll
* loop and emitted only when it differs from the previous reading.
*
* Exists for diagnostics. The operator reports the Sonos rapidly
* play-pause-play-pausing at the start of a track, and nothing in the
* diagnostics could see it: `player_state` records source / loading / error
* but not whether we are playing, `track_change` needs the queue index to
* move, and the heartbeat samples once every 45 seconds. A symptom that
* lasts a few seconds and changes no index fell straight through all three.
*
* This is the closest observation point we have to the renderer's own truth
* — the raw GetTransportInfo reading, before the two-poll confirmation and
* the UI's smoothing have had a chance to hide the wobble.
*
* **It samples at the poll cadence (1 Hz).** If the real oscillation is
* faster than that, what lands here is an aliased jagged sequence rather
* than the true waveform. That still answers the question that matters —
* whether the renderer is steadily PLAYING or repeatedly leaving that state
* — but it cannot measure the true period. If a captured episode comes back
* looking clean, the next instrument is burst sampling, not this one.
*/
data class TransportObservation(
/** [com.fabledsword.minstrel.player.output.upnp.TransportState] name. */
val state: String,
/** CurrentTransportStatus: false means the renderer reports an error. */
val statusOk: Boolean,
/** The renderer's 1-based queue position at this reading. */
val trackNumber: Int,
/** The renderer's reported position within the track. */
val positionMs: Long,
/** Whether the operator's last intent was to be playing. */
val playIntent: Boolean,
/** Monotonic stamp, so a consumer can measure gaps between readings. */
val atElapsedMs: Long,
)
@@ -10,11 +10,9 @@ import com.fabledsword.minstrel.models.TrackRef
import com.fabledsword.minstrel.player.PlayerController
import com.fabledsword.minstrel.player.PlayerFactory
import com.fabledsword.minstrel.player.RemotePlayerState
import com.fabledsword.minstrel.player.StreamTokenProvider
import com.fabledsword.minstrel.player.output.upnp.AVTransportClient
import com.fabledsword.minstrel.player.output.upnp.RenderingControlClient
import com.fabledsword.minstrel.player.output.upnp.SoapClient
import com.fabledsword.minstrel.player.output.upnp.SoapFaultException
import com.fabledsword.minstrel.player.output.upnp.TransportState
import com.fabledsword.minstrel.player.output.upnp.UpnpDiscoveryController
import com.fabledsword.minstrel.player.output.upnp.bareUdn
@@ -61,7 +59,7 @@ data class RouteSnapshot(
* - [OutputRoute.Protocol.SYSTEM] — MediaRouter.selectRoute (built-in,
* wired, Bluetooth)
* - [OutputRoute.Protocol.UPNP] — mint a signed stream token via
* [StreamTokenProvider.mint], drive the discovered renderer with
* [SonosQueueLoader], drive the discovered renderer with
* AVTransport.SetAVTransportURI + Play, pause local playback so
* audio yields to the network speaker
* - [OutputRoute.Protocol.CAST] / [OutputRoute.Protocol.SONOS] —
@@ -79,7 +77,7 @@ class OutputPickerController @Inject constructor(
private val upnpDiscovery: UpnpDiscoveryController,
private val playerController: PlayerController,
private val playerFactory: PlayerFactory,
private val streamTokens: StreamTokenProvider,
private val sonosQueue: SonosQueueLoader,
private val activeUpnpHolder: ActiveUpnpHolder,
private val remoteState: RemotePlayerState,
private val okHttp: OkHttpClient,
@@ -173,6 +171,7 @@ class OutputPickerController @Inject constructor(
playerFactory.dropEvents.collect { handleRemoteDrop() }
}
scope.launch { observeQueueChangesForSonosResync() }
scope.launch { observeQueueRepairRequests() }
scope.launch { observeIdleRevertWhileUpnp() }
scope.launch { observeSelectedRouteDisappearance() }
}
@@ -255,7 +254,7 @@ class OutputPickerController @Inject constructor(
* setMediaItems override clears holder.active + sets target so the
* imminent play() call drops (drops via isLoadingUpnp() = true). Then
* this collector observes the uiState.queue change and re-runs
* loadQueueOnSonos to push the new tracks to Sonos.
* SonosQueueLoader.load to push the new tracks to Sonos.
*
* Discrimination: selectUpnp's initial-load path doesn't change
* uiState.queue (the queue was already populated before route
@@ -286,6 +285,71 @@ class OutputPickerController @Inject constructor(
}
}
/**
* Rebuild the renderer's queue when playback stopped because the renderer
* ran off the end of a queue shorter than ours.
*
* [SonosQueueLoader] tolerates individual AddURIToQueue failures and
* gives up appending after a few consecutive ones
* -- Sonos rate-limits burst adds. Until this existed that left a short
* queue on the renderer and nothing to notice it: the renderer played what
* it had and stopped, and the app went on believing there were forty
* tracks left. [MinstrelForwardingPlayer] now compares GetMediaInfo's
* NrTracks against the local queue and asks for this.
*
* A full reload, not an incremental diff: the renderer's copy is known to
* be wrong, and the diff path reasons from what we *think* it holds, which
* is exactly the assumption that failed. The load re-seeks to the
* current track and plays, so recovery lands where the listener was.
*/
private suspend fun observeQueueRepairRequests() {
playerFactory.queueRepairEvents.collect {
val routeId = selectedUpnpRouteIdInternal.value
?: activeUpnpHolder.active.value?.routeId
if (routeId == null) {
Timber.w("Sonos queue repair skipped: no UPnP route selected")
return@collect
}
val state = playerController.uiState.value
if (state.queue.isEmpty()) {
Timber.w("Sonos queue repair skipped: local queue is empty")
return@collect
}
// Resume on the track AFTER the current one. The renderer stopped
// because it finished the last track it had; the local cursor is
// synced to that track, so reloading at it would replay something
// the listener just heard. The next one is what they never got.
val resumeAt = (state.queueIndex + 1).coerceAtMost(state.queue.size - 1)
repairSonosQueue(routeId, state.queue, resumeAt)
}
}
private suspend fun repairSonosQueue(
routeId: String,
queue: List<TrackRef>,
currentIndex: Int,
) = selectUpnpMutex.withLock {
val upnpRoute = upnpDiscovery.routes.value.firstOrNull { it.id == routeId }
val transport = upnpDiscovery.transportFor(routeId)
if (upnpRoute == null || transport == null) {
Timber.w("Sonos queue repair: route or transport gone for %s", routeId)
return@withLock
}
val outputRoute = OutputRoute.fromUpnpRoute(upnpRoute)
Timber.w(
"Sonos queue repair: reloading %d tracks on %s (resuming at index %d)",
queue.size, outputRoute.name, currentIndex,
)
runCatching {
sonosQueue.load(transport, outputRoute, queue, currentIndex)
}.onFailure { e ->
// Leave the route active: the renderer is reachable enough to have
// told us its queue length, so dropping to local would be a harsher
// remedy than letting the next stall re-decide.
Timber.w(e, "Sonos queue repair failed on %s", outputRoute.name)
}
}
/**
* Bring Sonos's native queue back in sync with the local queue after a
* mutation. Tries an incremental SOAP diff first (RemoveTrackRangeFromQueue
@@ -313,7 +377,7 @@ class OutputPickerController @Inject constructor(
return@withLock
}
val handledIncrementally = runCatching {
tryIncrementalResync(transport, oldIds, newQueue)
sonosQueue.tryIncrementalResync(transport, oldIds, newQueue)
}.getOrElse { e ->
Timber.w(e, "Sonos incremental resync errored; falling back to full reload")
false
@@ -337,7 +401,7 @@ class OutputPickerController @Inject constructor(
val rendering = renderingClientFor(routeId)
Timber.w("Sonos resync: full reload of %d tracks on %s", newQueue.size, outputRoute.name)
runCatching {
loadQueueOnSonos(transport, outputRoute, newQueue, newCurrentIndex)
sonosQueue.load(transport, outputRoute, newQueue, newCurrentIndex)
activeUpnpHolder.set(
ActiveUpnp(
routeId = routeId,
@@ -354,98 +418,6 @@ class OutputPickerController @Inject constructor(
}
}
/**
* Diff-based incremental Sonos queue sync. Returns true when the new
* queue can be produced from the old one with a remove-then-insert at
* the same middle slice -- the common-prefix and common-suffix portions
* stay untouched, and the current Sonos track must lie in the preserved
* prefix (otherwise the diff would orphan playback). Returns false to
* signal the caller to fall back to a full reload.
*/
private suspend fun tryIncrementalResync(
transport: AVTransportClient,
oldIds: List<String>,
newQueue: List<TrackRef>,
): Boolean {
val newIds = newQueue.map { it.id }
if (oldIds == newIds) return true
val prefixLen = commonPrefixLength(oldIds, newIds)
val suffixLen = commonSuffixLength(
oldIds.subList(prefixLen, oldIds.size),
newIds.subList(prefixLen, newIds.size),
)
val removedCount = oldIds.size - prefixLen - suffixLen
val addedCount = newIds.size - prefixLen - suffixLen
// Sonos's current track number is 1-based; compare against the
// preserved-prefix range as 0-based. If the current track is in
// the removed slice, incremental can't preserve playback -- caller
// falls back to full rebuild.
val currentSonosIdx0 = remoteState.trackNumber - 1
val canApply = currentSonosIdx0 in 0 until prefixLen
if (canApply) {
applyQueueDiff(transport, newQueue, prefixLen, removedCount, addedCount)
} else {
Timber.w(
"Sonos incremental: current track %d not in preserved prefix [0,%d); full rebuild",
currentSonosIdx0,
prefixLen,
)
}
return canApply
}
private suspend fun applyQueueDiff(
transport: AVTransportClient,
newQueue: List<TrackRef>,
prefixLen: Int,
removedCount: Int,
addedCount: Int,
) {
if (removedCount > 0) {
Timber.w(
"Sonos incremental: RemoveTrackRangeFromQueue start=%d count=%d",
prefixLen + 1,
removedCount,
)
transport.removeTrackRangeFromQueue(
startingIndex = prefixLen + 1,
numberOfTracks = removedCount,
)
}
if (addedCount == 0) return
Timber.w(
"Sonos incremental: AddURIToQueue x%d starting at position %d",
addedCount,
prefixLen + 1,
)
for (i in 0 until addedCount) {
val ref = newQueue[prefixLen + i]
val token = streamTokens.mint(ref.id)
transport.addURIToQueue(
uri = token.url,
mime = token.mime,
title = token.title,
enqueuedURIPosition = prefixLen + i + 1,
)
if (i > 0) delay(EXTEND_THROTTLE_MS)
}
}
private fun commonPrefixLength(a: List<String>, b: List<String>): Int {
val limit = minOf(a.size, b.size)
for (i in 0 until limit) {
if (a[i] != b[i]) return i
}
return limit
}
private fun commonSuffixLength(a: List<String>, b: List<String>): Int {
val limit = minOf(a.size, b.size)
for (i in 0 until limit) {
if (a[a.size - 1 - i] != b[b.size - 1 - i]) return i
}
return limit
}
/**
* Called when the active UPnP route drops unexpectedly (the poll loop's
@@ -539,7 +511,7 @@ class OutputPickerController @Inject constructor(
* 1. Pause local so the user doesn't keep hearing local audio.
* 2. Set target early so ForwardingPlayer drops transport taps
* while the 17-second queue load is in progress.
* 3. Wire active LAST (after loadQueueOnSonos) so SOAP commands
* 3. Wire active LAST (after the queue load) so SOAP commands
* are never routed to a half-loaded Sonos queue.
*/
private suspend fun selectUpnp(route: OutputRoute) = selectUpnpMutex.withLock {
@@ -580,7 +552,7 @@ class OutputPickerController @Inject constructor(
// taps don't hit Sonos's stale state from a prior session.
activeUpnpHolder.setTarget(effectiveRoute.id)
runCatching {
loadQueueOnSonos(transport, effectiveRoute, uiState.queue, uiState.queueIndex)
sonosQueue.load(transport, effectiveRoute, uiState.queue, uiState.queueIndex)
// Wire active LAST -- SOAP path is now safe to use.
activeUpnpHolder.set(
ActiveUpnp(
@@ -697,108 +669,6 @@ class OutputPickerController @Inject constructor(
return if (i >= 0) segments.getOrNull(i + 1) else null
}
private suspend fun loadQueueOnSonos(
transport: AVTransportClient,
route: OutputRoute,
queue: List<TrackRef>,
currentIndex: Int,
) {
Timber.w("UPnP select: clear queue on %s", route.name)
transport.removeAllTracksFromQueue()
val initialEnd = (currentIndex + 1).coerceAtMost(queue.size)
val initialBatch = queue.subList(0, initialEnd)
Timber.w(
"UPnP select: add %d initial tracks (currentIndex=%d, totalQueue=%d)",
initialBatch.size, currentIndex, queue.size,
)
initialBatch.forEachIndexed { idx, ref ->
val token = streamTokens.mint(ref.id)
transport.addURIToQueue(
uri = token.url,
mime = token.mime,
title = token.title,
enqueuedURIPosition = idx + 1,
)
}
val coordinatorUdn = route.id.bareUdn()
val queueUri = "x-rincon-queue:$coordinatorUdn#0"
Timber.w("UPnP select: SetAVTransportURI %s", queueUri)
transport.setAVTransportURI(queueUri, "")
Timber.w("UPnP select: Seek to track %d", currentIndex + 1)
transport.seekToTrack(currentIndex + 1)
Timber.w("UPnP select: Play")
transport.play()
Timber.w("UPnP select: initial done; backgrounding remainder")
val remaining = queue.drop(initialEnd)
if (remaining.isNotEmpty()) {
scope.launch { extendQueueOnSonos(transport, route, remaining, initialEnd) }
}
}
/**
* Background-append tracks after activation. Runs concurrently with
* Sonos playback. Cancels if the user disconnects from this route
* (active.routeId changes or becomes null). Tolerates individual
* AddURIToQueue failures — log and continue so some tracks loaded
* is better than zero tracks loaded.
*/
private suspend fun extendQueueOnSonos(
transport: AVTransportClient,
route: OutputRoute,
tracks: List<TrackRef>,
startPosition: Int,
) {
Timber.w(
"UPnP extend: appending %d tracks starting at position %d",
tracks.size, startPosition + 1,
)
var consecutiveFailures = 0
var succeeded = 0
var aborted = false
for ((i, ref) in tracks.withIndex()) {
if (aborted) break
if (activeUpnpHolder.active.value?.routeId != route.id) {
Timber.w("UPnP extend: cancelled at offset %d (route changed)", i)
aborted = true
} else {
val outcome = runCatching {
val token = streamTokens.mint(ref.id)
transport.addURIToQueue(
uri = token.url,
mime = token.mime,
title = token.title,
enqueuedURIPosition = startPosition + i + 1,
)
}
if (outcome.isSuccess) {
consecutiveFailures = 0
succeeded += 1
// Throttle the burst so we don't tickle Sonos's burst-add
// rejection -- logcat 2026-06-04 showed 33 consecutive
// failures clustered at ~10ms intervals once offset 39 was
// reached, which looks like a rate-limit kicking in. The
// delay is small enough that extending 100 tracks adds
// only ~5s to background work that's already async.
delay(EXTEND_THROTTLE_MS)
} else {
consecutiveFailures += 1
val e = outcome.exceptionOrNull()
val detail = (e as? SoapFaultException)?.let {
"code=${it.code} desc=${it.description}"
} ?: e?.message
Timber.w(e, "UPnP extend: append failed at offset %d -- %s", i, detail)
if (consecutiveFailures >= EXTEND_ABORT_AFTER_FAILURES) {
Timber.w(
"UPnP extend: aborting after %d consecutive failures",
consecutiveFailures,
)
aborted = true
}
}
}
}
Timber.w("UPnP extend: done (%d / %d appended)", succeeded, tracks.size)
}
private fun renderingClientFor(routeId: String): RenderingControlClient? {
val rcUrl = upnpDiscovery.routes.value
@@ -830,9 +700,6 @@ class OutputPickerController @Inject constructor(
}
private companion object {
const val EXTEND_ABORT_AFTER_FAILURES = 3
const val EXTEND_THROTTLE_MS = 50L
// 5 minutes of continuous non-playing on a UPnP route before we
// revert to the phone speaker, so a stale Sonos selection can't make
// a later "tap play" do nothing.
@@ -0,0 +1,316 @@
package com.fabledsword.minstrel.player.output
import com.fabledsword.minstrel.di.ApplicationScope
import com.fabledsword.minstrel.models.TrackRef
import com.fabledsword.minstrel.player.RemotePlayerState
import com.fabledsword.minstrel.player.StreamTokenProvider
import com.fabledsword.minstrel.player.output.upnp.AVTransportClient
import com.fabledsword.minstrel.player.output.upnp.SoapFaultException
import com.fabledsword.minstrel.player.output.upnp.bareUdn
import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.delay
import kotlinx.coroutines.launch
import timber.log.Timber
import javax.inject.Inject
import javax.inject.Singleton
/**
* Owns the shape of a Sonos renderer's native queue: loading it, growing it,
* diffing it against local queue mutations, and — the part that was missing —
* confirming the renderer actually took what we sent.
*
* Split out of [OutputPickerController], which is about *which route is
* selected*. How many tracks the renderer is holding is a separate concern
* with its own failure modes, and it had grown large enough to hide one:
* every write here is a SOAP call that can fail individually, and until
* [verifyQueueLength] nothing ever read the result back.
*/
@Singleton
class SonosQueueLoader @Inject constructor(
@ApplicationScope private val scope: CoroutineScope,
private val streamTokens: StreamTokenProvider,
private val activeUpnpHolder: ActiveUpnpHolder,
private val remoteState: RemotePlayerState,
) {
suspend fun load(
transport: AVTransportClient,
route: OutputRoute,
queue: List<TrackRef>,
currentIndex: Int,
) {
Timber.w("UPnP select: clear queue on %s", route.name)
transport.removeAllTracksFromQueue()
val initialEnd = (currentIndex + 1).coerceAtMost(queue.size)
val initialBatch = queue.subList(0, initialEnd)
Timber.w(
"UPnP select: add %d initial tracks (currentIndex=%d, totalQueue=%d)",
initialBatch.size, currentIndex, queue.size,
)
initialBatch.forEachIndexed { idx, ref ->
val token = streamTokens.mint(ref.id)
transport.addURIToQueue(
uri = token.url,
mime = token.mime,
title = token.title,
enqueuedURIPosition = idx + 1,
)
}
val coordinatorUdn = route.id.bareUdn()
val queueUri = "x-rincon-queue:$coordinatorUdn#0"
Timber.w("UPnP select: SetAVTransportURI %s", queueUri)
transport.setAVTransportURI(queueUri, "")
Timber.w("UPnP select: Seek to track %d", currentIndex + 1)
transport.seekToTrack(currentIndex + 1)
Timber.w("UPnP select: Play")
transport.play()
Timber.w("UPnP select: initial done; backgrounding remainder")
val remaining = queue.drop(initialEnd)
// Verify even when there is no tail to append: the initial batch is
// sent the same way and can be dropped the same way.
scope.launch {
if (remaining.isNotEmpty()) {
extendQueueOnSonos(transport, route, remaining, initialEnd)
}
verifyQueueLength(transport, route, queue)
}
}
/**
* Background-append tracks after activation. Runs concurrently with Sonos
* playback. Cancels if the user disconnects from this route (active.routeId
* changes or becomes null). Correctness of the result is [verifyQueueLength]'s
* job, not this function's.
*/
private suspend fun extendQueueOnSonos(
transport: AVTransportClient,
route: OutputRoute,
tracks: List<TrackRef>,
startPosition: Int,
) {
Timber.w(
"UPnP extend: appending %d tracks starting at position %d",
tracks.size, startPosition + 1,
)
val succeeded = appendTracksToQueue(transport, route, tracks, startPosition)
Timber.w("UPnP extend: done (%d / %d appended)", succeeded, tracks.size)
}
/**
* Confirm the renderer holds as many tracks as we sent, and append the
* tail it dropped.
*
* [appendTracksToQueue] tolerates individual failures and gives up after
* [EXTEND_ABORT_AFTER_FAILURES] consecutive ones, because Sonos rate-limits
* burst adds (logcat 2026-06-04: 33 consecutive failures once offset 39 was
* reached). That is the right call in the moment — some tracks loaded beats
* none — but it used to be the end of the story, and the renderer was left
* holding a queue shorter than ours with nothing aware of it. It then
* played what it had and stopped, which looked exactly like playback dying
* for no reason.
*
* Sonos appends sequentially, so a short queue means a missing tail: taking
* `fullQueue.drop(nrTracks)` is the gap. Bounded at [VERIFY_ROUNDS] passes
* so a renderer that refuses to grow can't spin here forever.
*/
@Suppress("ReturnCount") // each bail-out is a distinct reason to stop verifying
private suspend fun verifyQueueLength(
transport: AVTransportClient,
route: OutputRoute,
fullQueue: List<TrackRef>,
) {
repeat(VERIFY_ROUNDS) { round ->
if (activeUpnpHolder.active.value?.routeId != route.id) return
val nrTracks = runCatching { transport.getMediaInfo().nrTracks }
.getOrElse { e ->
Timber.w(e, "UPnP verify: GetMediaInfo failed on %s", route.name)
return
}
// 0 means the renderer told us nothing usable, not that its queue
// is empty. Guessing "empty" here would re-send the whole queue to
// a renderer that is playing it perfectly well.
if (nrTracks <= 0) {
Timber.w("UPnP verify: no usable NrTracks from %s; skipping", route.name)
return
}
if (nrTracks >= fullQueue.size) {
Timber.w("UPnP verify: renderer holds %d tracks, queue intact", nrTracks)
return
}
val missing = fullQueue.drop(nrTracks)
Timber.w(
"UPnP verify: %s holds %d of %d tracks; appending %d missing (round %d)",
route.name, nrTracks, fullQueue.size, missing.size, round + 1,
)
appendTracksToQueue(transport, route, missing, nrTracks)
}
Timber.w("UPnP verify: gave up repairing queue length on %s", route.name)
}
/**
* Append [tracks] at [startPosition] (0-based), returning how many landed.
* Tolerates individual AddURIToQueue failures — log and continue so some
* tracks loaded is better than zero tracks loaded — and stops early after
* [EXTEND_ABORT_AFTER_FAILURES] consecutive ones.
*/
private suspend fun appendTracksToQueue(
transport: AVTransportClient,
route: OutputRoute,
tracks: List<TrackRef>,
startPosition: Int,
): Int {
var consecutiveFailures = 0
var succeeded = 0
var aborted = false
for ((i, ref) in tracks.withIndex()) {
if (aborted) break
if (activeUpnpHolder.active.value?.routeId != route.id) {
Timber.w("UPnP extend: cancelled at offset %d (route changed)", i)
aborted = true
} else {
val outcome = runCatching {
val token = streamTokens.mint(ref.id)
transport.addURIToQueue(
uri = token.url,
mime = token.mime,
title = token.title,
enqueuedURIPosition = startPosition + i + 1,
)
}
if (outcome.isSuccess) {
consecutiveFailures = 0
succeeded += 1
// Throttle the burst so we don't tickle Sonos's burst-add
// rejection -- logcat 2026-06-04 showed 33 consecutive
// failures clustered at ~10ms intervals once offset 39 was
// reached, which looks like a rate-limit kicking in. The
// delay is small enough that extending 100 tracks adds
// only ~5s to background work that's already async.
delay(EXTEND_THROTTLE_MS)
} else {
consecutiveFailures += 1
val e = outcome.exceptionOrNull()
val detail = (e as? SoapFaultException)?.let {
"code=${it.code} desc=${it.description}"
} ?: e?.message
Timber.w(e, "UPnP extend: append failed at offset %d -- %s", i, detail)
if (consecutiveFailures >= EXTEND_ABORT_AFTER_FAILURES) {
Timber.w(
"UPnP extend: aborting after %d consecutive failures",
consecutiveFailures,
)
aborted = true
}
}
}
}
return succeeded
}
/**
* Diff-based incremental Sonos queue sync. Returns true when the new
* queue can be produced from the old one with a remove-then-insert at
* the same middle slice -- the common-prefix and common-suffix portions
* stay untouched, and the current Sonos track must lie in the preserved
* prefix (otherwise the diff would orphan playback). Returns false to
* signal the caller to fall back to a full reload.
*/
suspend fun tryIncrementalResync(
transport: AVTransportClient,
oldIds: List<String>,
newQueue: List<TrackRef>,
): Boolean {
val newIds = newQueue.map { it.id }
if (oldIds == newIds) return true
val prefixLen = commonPrefixLength(oldIds, newIds)
val suffixLen = commonSuffixLength(
oldIds.subList(prefixLen, oldIds.size),
newIds.subList(prefixLen, newIds.size),
)
val removedCount = oldIds.size - prefixLen - suffixLen
val addedCount = newIds.size - prefixLen - suffixLen
// Sonos's current track number is 1-based; compare against the
// preserved-prefix range as 0-based. If the current track is in
// the removed slice, incremental can't preserve playback -- caller
// falls back to full rebuild.
val currentSonosIdx0 = remoteState.trackNumber - 1
val canApply = currentSonosIdx0 in 0 until prefixLen
if (canApply) {
applyQueueDiff(transport, newQueue, prefixLen, removedCount, addedCount)
} else {
Timber.w(
"Sonos incremental: current track %d not in preserved prefix [0,%d); full rebuild",
currentSonosIdx0,
prefixLen,
)
}
return canApply
}
private suspend fun applyQueueDiff(
transport: AVTransportClient,
newQueue: List<TrackRef>,
prefixLen: Int,
removedCount: Int,
addedCount: Int,
) {
if (removedCount > 0) {
Timber.w(
"Sonos incremental: RemoveTrackRangeFromQueue start=%d count=%d",
prefixLen + 1,
removedCount,
)
transport.removeTrackRangeFromQueue(
startingIndex = prefixLen + 1,
numberOfTracks = removedCount,
)
}
if (addedCount == 0) return
Timber.w(
"Sonos incremental: AddURIToQueue x%d starting at position %d",
addedCount,
prefixLen + 1,
)
for (i in 0 until addedCount) {
val ref = newQueue[prefixLen + i]
val token = streamTokens.mint(ref.id)
transport.addURIToQueue(
uri = token.url,
mime = token.mime,
title = token.title,
enqueuedURIPosition = prefixLen + i + 1,
)
if (i > 0) delay(EXTEND_THROTTLE_MS)
}
}
private fun commonPrefixLength(a: List<String>, b: List<String>): Int {
val limit = minOf(a.size, b.size)
for (i in 0 until limit) {
if (a[i] != b[i]) return i
}
return limit
}
private fun commonSuffixLength(a: List<String>, b: List<String>): Int {
val limit = minOf(a.size, b.size)
for (i in 0 until limit) {
if (a[a.size - 1 - i] != b[b.size - 1 - i]) return i
}
return limit
}
private companion object {
// Abort the append loop after this many consecutive AddURIToQueue
// failures; Sonos rate-limits burst adds and a wall of failures means
// it has stopped accepting, not that the next one might land.
const val EXTEND_ABORT_AFTER_FAILURES = 3
const val EXTEND_THROTTLE_MS = 50L
// Verify/repair passes after a queue load. Two: one to catch the
// common case (a rate-limit burst dropped a chunk), one to catch a
// repair that itself got rate-limited. Beyond that the renderer is
// refusing for a reason retrying won't fix, and the stall watchdog
// becomes the backstop.
const val VERIFY_ROUNDS = 2
}
}
@@ -211,6 +211,34 @@ class AVTransportClient(
)
}
/**
* What the renderer believes it is holding: how many tracks are in its
* queue, and the URI the transport is pointed at.
*
* We load the queue with AddURIToQueue and, until this existed, never
* read it back — so a partially-applied load was invisible. Sonos
* rate-limits burst adds (logcat 2026-06-04: 33 consecutive failures once
* offset 39 was reached), and [OutputPickerController]'s extend loop gives
* up after a few of those and leaves a short queue behind. The renderer
* then plays what it actually has and stops, correctly, at an end the app
* did not know existed.
*
* NrTracks is the cheap authoritative answer, so queue truncation becomes
* something we can detect and repair rather than infer.
*/
suspend fun getMediaInfo(): MediaInfo {
val result = soap.call(
controlUrl = controlUrl,
serviceType = SERVICE_TYPE,
action = "GetMediaInfo",
args = mapOf("InstanceID" to "0"),
)
return MediaInfo(
nrTracks = result["NrTracks"]?.toIntOrNull() ?: 0,
currentUri = result["CurrentURI"].orEmpty(),
)
}
suspend fun getTransportInfo(): TransportInfo {
val result = soap.call(
controlUrl = controlUrl,
@@ -298,6 +326,14 @@ data class PositionInfo(
val trackDurationMs: Long,
)
/**
* [nrTracks] is the renderer's own count of its queue — 0 when it reports
* nothing, which callers must read as "unknown", never as "empty". A
* renderer that does not implement GetMediaInfo usefully must not be
* mistaken for one with an empty queue.
*/
data class MediaInfo(val nrTracks: Int, val currentUri: String)
enum class TransportState { PLAYING, PAUSED, STOPPED, TRANSITIONING, UNKNOWN }
/**
@@ -0,0 +1,128 @@
package com.fabledsword.minstrel.diagnostics
import com.fabledsword.minstrel.player.TransportObservation
import org.junit.jupiter.api.Test
import kotlin.test.assertEquals
import kotlin.test.assertNotNull
import kotlin.test.assertNull
/**
* The rule deciding when renderer transport changes are worth recording as an
* episode. Worth pinning because both failure directions are costly: too eager
* and every track transition writes a summary that buries the real one, too
* shy and the operator's stutter goes unmeasured for another month.
*/
class TransportFlapDetectorTest {
private fun obs(state: String, atMs: Long, track: Int = 1, posMs: Long = 0L) =
TransportObservation(
state = state,
statusOk = true,
trackNumber = track,
positionMs = posMs,
playIntent = true,
atElapsedMs = atMs,
)
/**
* PLAYING -> TRANSITIONING -> PLAYING is what a queue advance looks like.
* It happens on every single track and must never be recorded as a fault.
*/
@Test
fun `an ordinary track transition is not an episode`() {
val d = TransportFlapDetector()
assertNull(d.onChange(obs("PLAYING", 0)))
assertNull(d.onChange(obs("TRANSITIONING", 1_000)))
assertNull(d.onChange(obs("PLAYING", 2_000)))
}
@Test
fun `four changes inside the window is an episode`() {
val d = TransportFlapDetector()
d.onChange(obs("PLAYING", 0))
d.onChange(obs("STOPPED", 500))
d.onChange(obs("PLAYING", 1_000))
// assertNotNull returns the value, so the asserts below need no cast.
val episode = assertNotNull(d.onChange(obs("STOPPED", 1_500)))
assertEquals(4, episode.size)
assertEquals(
listOf("PLAYING", "STOPPED", "PLAYING", "STOPPED"),
episode.map { it.state },
)
}
/**
* Changes spread thinly are normal listening — a few track advances over
* a couple of minutes must not accumulate into a false episode.
*/
@Test
fun `changes spread beyond the window never accumulate`() {
val d = TransportFlapDetector()
repeat(20) { i ->
assertNull(d.onChange(obs("PLAYING", i * 10_000L)))
}
}
/** The window slides: old readings age out rather than counting forever. */
@Test
fun `readings older than the window are dropped`() {
val d = TransportFlapDetector()
d.onChange(obs("PLAYING", 0))
d.onChange(obs("STOPPED", 1_000))
// Long gap — the two above are now stale.
assertNull(d.onChange(obs("PLAYING", 30_000)))
assertNull(d.onChange(obs("STOPPED", 30_500)))
// Only three fresh readings so far.
assertNull(d.onChange(obs("PLAYING", 31_000)))
assertNotNull(d.onChange(obs("STOPPED", 31_500)))
}
/**
* A fault that persists produces a change every poll. Without the cooldown
* every one of them would write a summary, which is exactly the noise that
* makes a diagnostics dump unreadable.
*/
@Test
fun `a sustained fault reports one episode, not one per reading`() {
val d = TransportFlapDetector()
var episodes = 0
repeat(40) { i ->
if (d.onChange(obs(if (i % 2 == 0) "PLAYING" else "STOPPED", i * 500L)) != null) {
episodes++
}
}
assertEquals(1, episodes)
}
/** Past the cooldown, a fresh episode is worth recording again. */
@Test
fun `a later episode reports again once the cooldown has passed`() {
val d = TransportFlapDetector()
repeat(4) { d.onChange(obs("PLAYING", it * 500L)) }
val second = (0 until 4).map { d.onChange(obs("STOPPED", 90_000 + it * 500L)) }
assertEquals(1, second.count { it != null })
}
@Test
fun `reset forgets the window and the cooldown`() {
val d = TransportFlapDetector()
repeat(4) { d.onChange(obs("PLAYING", it * 500L)) }
d.reset()
repeat(3) { d.onChange(obs("PLAYING", 3_000 + it * 500L)) }
// A 4th change after reset is a new episode, cooldown notwithstanding.
assertNotNull(d.onChange(obs("STOPPED", 5_000)))
}
/** The episode is a snapshot — later readings must not mutate it. */
@Test
fun `a returned episode is not mutated by later readings`() {
val d = TransportFlapDetector()
d.onChange(obs("PLAYING", 0))
d.onChange(obs("STOPPED", 500))
d.onChange(obs("PLAYING", 1_000))
val episode = assertNotNull(d.onChange(obs("STOPPED", 1_500)))
val sizeAtCapture = episode.size
repeat(5) { d.onChange(obs("PLAYING", 2_000 + it * 500L)) }
assertEquals(sizeAtCapture, episode.size)
}
}
@@ -19,15 +19,35 @@ class RemoteStallWatchdogTest {
playIntent: Boolean = true,
positionMs: Long = 0L,
nowMs: Long = 0L,
) = onPoll(trackUri, state, statusOk, playIntent, positionMs, nowMs)
queue: RemoteStallWatchdog.QueueState = RemoteStallWatchdog.QueueState.UNKNOWN,
) = onPoll(
RemoteStallWatchdog.Poll(
trackUri = trackUri,
state = state,
statusOk = statusOk,
playIntent = playIntent,
positionMs = positionMs,
nowMs = nowMs,
queue = queue,
),
)
/** Drive [n] stopped polls and return the last decision. */
private fun RemoteStallWatchdog.stopFor(
n: Int,
nowMs: Long = 0L,
queue: RemoteStallWatchdog.QueueState = RemoteStallWatchdog.QueueState.UNKNOWN,
trackUri: String = uri,
): RemoteStallWatchdog.Decision {
var last: RemoteStallWatchdog.Decision = RemoteStallWatchdog.Decision.None
repeat(n) { last = poll(state = TransportState.STOPPED, nowMs = nowMs) }
repeat(n) {
last = poll(
trackUri = trackUri,
state = TransportState.STOPPED,
nowMs = nowMs,
queue = queue,
)
}
return last
}
@@ -174,6 +194,106 @@ class RemoteStallWatchdogTest {
assertEquals(60_000L, again.resumeAtMs)
}
// A stopped renderer can mean three different things. Before QueueState
// they were indistinguishable, and all three were treated as a stall.
/**
* The regression that mattered most: reaching the end of the queue is how
* every listening session ends. Treating it as a stall meant retrying the
* last track three times and then raising a `stalled` error for playback
* that finished perfectly normally.
*/
@Test
fun `reaching the end of the queue is not a stall`() {
val w = RemoteStallWatchdog()
repeat(20) {
assertIs<RemoteStallWatchdog.Decision.None>(
w.stopFor(1, nowMs = it * 1_000L, queue = RemoteStallWatchdog.QueueState.COMPLETE),
)
}
}
/** And it must not quietly spend the budget it never needed. */
@Test
fun `a completed queue leaves the attempt budget untouched`() {
val w = RemoteStallWatchdog()
w.stopFor(5, queue = RemoteStallWatchdog.QueueState.COMPLETE)
// Same track, now genuinely stalled: full budget, first attempt.
val decision = w.stopFor(3, nowMs = 30_000L)
assertIs<RemoteStallWatchdog.Decision.Resume>(decision)
assertEquals(1, decision.attempt)
}
/**
* The bug behind all of this: the renderer stopped because it reached the
* end of a queue we failed to fully load. Re-playing the finished track is
* the wrong remedy — the queue is what's broken.
*/
@Test
fun `running off the end of a truncated queue asks for a repair`() {
val w = RemoteStallWatchdog()
val decision = w.stopFor(3, queue = RemoteStallWatchdog.QueueState.TRUNCATED)
assertIs<RemoteStallWatchdog.Decision.RepairQueue>(decision)
assertEquals(1, decision.attempt)
}
/** A renderer with tracks left that stopped anyway really has stalled. */
@Test
fun `stopping mid-queue is still a stall`() {
val w = RemoteStallWatchdog()
val decision = w.stopFor(3, queue = RemoteStallWatchdog.QueueState.HAS_MORE)
assertIs<RemoteStallWatchdog.Decision.Resume>(decision)
}
/**
* A renderer that doesn't report NrTracks usefully must keep the old
* behaviour rather than being told its queue is fine or broken.
*/
@Test
fun `an unknown queue state falls back to resuming`() {
val w = RemoteStallWatchdog()
assertIs<RemoteStallWatchdog.Decision.Resume>(
w.stopFor(3, queue = RemoteStallWatchdog.QueueState.UNKNOWN),
)
}
/** Repairs are bounded by the same budget, so a renderer that will not
* grow its queue stops being asked. */
@Test
fun `repairs are capped and then it gives up`() {
val w = RemoteStallWatchdog()
val truncated = RemoteStallWatchdog.QueueState.TRUNCATED
assertIs<RemoteStallWatchdog.Decision.RepairQueue>(
w.stopFor(3, nowMs = 0L, queue = truncated),
)
assertIs<RemoteStallWatchdog.Decision.RepairQueue>(
w.stopFor(1, nowMs = 5_000L, queue = truncated),
)
assertIs<RemoteStallWatchdog.Decision.RepairQueue>(
w.stopFor(1, nowMs = 10_000L, queue = truncated),
)
assertIs<RemoteStallWatchdog.Decision.GiveUp>(
w.stopFor(1, nowMs = 15_000L, queue = truncated),
)
}
/**
* A successful repair adds tracks, so the renderer moves on to one it had
* never seen. That is a new track, which restores the budget by the same
* rule any other track change does.
*/
@Test
fun `a repair that works hands the next track a full budget`() {
val w = RemoteStallWatchdog()
assertIs<RemoteStallWatchdog.Decision.RepairQueue>(
w.stopFor(3, queue = RemoteStallWatchdog.QueueState.TRUNCATED),
)
w.poll(trackUri = other, state = TransportState.PLAYING, nowMs = 6_000L)
val next = w.stopFor(3, nowMs = 30_000L, trackUri = other)
assertIs<RemoteStallWatchdog.Decision.Resume>(next)
assertEquals(1, next.attempt)
}
@Test
fun `reset forgets everything`() {
val w = RemoteStallWatchdog()
@@ -183,6 +183,52 @@ class AVTransportClientTest {
}
}
@Test
fun `getMediaInfo parses NrTracks and CurrentURI`() = runTest {
server.enqueue(
MockResponse().setBody(
"""<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
<s:Body>
<u:GetMediaInfoResponse
xmlns:u="urn:schemas-upnp-org:service:AVTransport:1">
<NrTracks>42</NrTracks>
<MediaDuration>0:00:00</MediaDuration>
<CurrentURI>x-rincon-queue:RINCON_ABC#0</CurrentURI>
</u:GetMediaInfoResponse>
</s:Body>
</s:Envelope>""".trimIndent(),
),
)
val info = client.getMediaInfo()
assertEquals(42, info.nrTracks)
assertEquals("x-rincon-queue:RINCON_ABC#0", info.currentUri)
}
/**
* A renderer that omits NrTracks reads as 0, which callers must treat as
* "unknown". Parsing it as anything else would let an unhelpful renderer
* be mistaken for one with an empty queue — and the repair path would
* then re-send the whole queue to a device playing it perfectly well.
*/
@Test
fun `getMediaInfo reports zero when the renderer omits NrTracks`() = runTest {
server.enqueue(
MockResponse().setBody(
"""<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
<s:Body>
<u:GetMediaInfoResponse
xmlns:u="urn:schemas-upnp-org:service:AVTransport:1">
<CurrentURI>http://x/y.mp3</CurrentURI>
</u:GetMediaInfoResponse>
</s:Body>
</s:Envelope>""".trimIndent(),
),
)
assertEquals(0, client.getMediaInfo().nrTracks)
}
private fun emptyResponse(action: String): MockResponse = MockResponse().setBody(
"""<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">