fix(player): verify the Sonos queue actually landed — #2728
android / Build + lint + test (push) Failing after 1m18s
android / Build + lint + test (push) Failing after 1m18s
The renderer's queue was written and never read back. loadQueueOnSonos background-appends the tail one AddURIToQueue at a time and gives up after 3 consecutive failures; Sonos rate-limits burst adds, so that happens. The renderer was then left holding fewer tracks than we believed, played what it actually had, and stopped — which looked exactly like playback dying for no reason. GetMediaInfo's NrTracks is the cheap authoritative answer and was not being asked for anywhere in the app. Now: - verifyQueueLength after every load (including when there is no tail to append — the initial batch can be dropped the same way), appending what the renderer is missing, bounded at 2 passes. - RemoteStallWatchdog gains QueueState, so a stop is classified rather than assumed: a stream that died resumes, a truncated queue gets repaired at the next track, and a queue that simply ended does nothing at all. That last case was a bug shipped in #2700: the normal end of a queue is a confirmed STOPPED with play intent, so every cast session would have ended with three resume attempts and a `stalled` error for playback that finished perfectly. No test described the end of a queue, so CI had nothing to catch it with. Queue reads are gated on the transport being stopped and cached for 5s, so this never becomes a third SOAP call per second.
This commit is contained in:
+93
-12
@@ -48,12 +48,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 +71,24 @@ 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 = {},
|
||||
)
|
||||
|
||||
private val scope = CoroutineScope(SupervisorJob() + Dispatchers.IO)
|
||||
private val handler = Handler(delegate.applicationLooper)
|
||||
private var pollJob: Job? = null
|
||||
@@ -97,6 +111,12 @@ 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
|
||||
|
||||
// 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.
|
||||
@@ -516,7 +536,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)
|
||||
@@ -613,12 +633,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 +661,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 +679,55 @@ 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
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* 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 +820,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
|
||||
|
||||
@@ -84,6 +84,17 @@ 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()
|
||||
|
||||
fun build(): Player {
|
||||
val exo = buildExoPlayer()
|
||||
return MinstrelForwardingPlayer(
|
||||
@@ -92,8 +103,11 @@ 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) },
|
||||
),
|
||||
)
|
||||
}
|
||||
|
||||
|
||||
@@ -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. */
|
||||
|
||||
+152
-8
@@ -173,6 +173,7 @@ class OutputPickerController @Inject constructor(
|
||||
playerFactory.dropEvents.collect { handleRemoteDrop() }
|
||||
}
|
||||
scope.launch { observeQueueChangesForSonosResync() }
|
||||
scope.launch { observeQueueRepairRequests() }
|
||||
scope.launch { observeIdleRevertWhileUpnp() }
|
||||
scope.launch { observeSelectedRouteDisappearance() }
|
||||
}
|
||||
@@ -286,6 +287,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.
|
||||
*
|
||||
* [extendQueueOnSonos] tolerates individual AddURIToQueue failures and
|
||||
* gives up entirely after [EXTEND_ABORT_AFTER_FAILURES] 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. loadQueueOnSonos 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 {
|
||||
loadQueueOnSonos(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
|
||||
@@ -730,17 +796,21 @@ class OutputPickerController @Inject constructor(
|
||||
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) }
|
||||
// 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). Tolerates individual
|
||||
* AddURIToQueue failures — log and continue so some tracks loaded
|
||||
* is better than zero tracks loaded.
|
||||
* 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,
|
||||
@@ -752,6 +822,73 @@ class OutputPickerController @Inject constructor(
|
||||
"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
|
||||
@@ -797,7 +934,7 @@ class OutputPickerController @Inject constructor(
|
||||
}
|
||||
}
|
||||
}
|
||||
Timber.w("UPnP extend: done (%d / %d appended)", succeeded, tracks.size)
|
||||
return succeeded
|
||||
}
|
||||
|
||||
private fun renderingClientFor(routeId: String): RenderingControlClient? {
|
||||
@@ -833,6 +970,13 @@ class OutputPickerController @Inject constructor(
|
||||
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
|
||||
|
||||
// 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.
|
||||
|
||||
+36
@@ -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 }
|
||||
|
||||
/**
|
||||
|
||||
+122
-2
@@ -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()
|
||||
|
||||
+46
@@ -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/">
|
||||
|
||||
Reference in New Issue
Block a user