From 8e21bce103b585e55e61692569033830dae5b8b6 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 17 Aug 2026 22:29:54 -0400 Subject: [PATCH] =?UTF-8?q?fix(player):=20verify=20the=20Sonos=20queue=20a?= =?UTF-8?q?ctually=20landed=20=E2=80=94=20#2728?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- .../player/MinstrelForwardingPlayer.kt | 105 ++++++++++-- .../minstrel/player/PlayerFactory.kt | 18 +- .../minstrel/player/RemoteStallWatchdog.kt | 117 ++++++++++--- .../player/output/OutputPickerController.kt | 160 +++++++++++++++++- .../player/output/upnp/AVTransportClient.kt | 36 ++++ .../player/RemoteStallWatchdogTest.kt | 124 +++++++++++++- .../output/upnp/AVTransportClientTest.kt | 46 +++++ 7 files changed, 555 insertions(+), 51 deletions(-) diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt index 7bc0bb40..fcb55d3a 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt @@ -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 diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt index 745e6b8c..05bda717 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt @@ -84,6 +84,17 @@ class PlayerFactory @Inject constructor( ) val stallEvents: SharedFlow = 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( + replay = 0, + extraBufferCapacity = 1, + onBufferOverflow = BufferOverflow.DROP_OLDEST, + ) + val queueRepairEvents: SharedFlow = 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) }, + ), ) } diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/RemoteStallWatchdog.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/RemoteStallWatchdog.kt index ed993480..a21944cc 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/RemoteStallWatchdog.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/RemoteStallWatchdog.kt @@ -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. */ diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/output/OutputPickerController.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/output/OutputPickerController.kt index 80d9a6b1..57b2860c 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/output/OutputPickerController.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/output/OutputPickerController.kt @@ -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, + 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, + ) { + 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, + 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. diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClient.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClient.kt index 6670db0c..0f08c370 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClient.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClient.kt @@ -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 } /** diff --git a/android/app/src/test/java/com/fabledsword/minstrel/player/RemoteStallWatchdogTest.kt b/android/app/src/test/java/com/fabledsword/minstrel/player/RemoteStallWatchdogTest.kt index 144db35c..c3da481f 100644 --- a/android/app/src/test/java/com/fabledsword/minstrel/player/RemoteStallWatchdogTest.kt +++ b/android/app/src/test/java/com/fabledsword/minstrel/player/RemoteStallWatchdogTest.kt @@ -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( + 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(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(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(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( + 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( + w.stopFor(3, nowMs = 0L, queue = truncated), + ) + assertIs( + w.stopFor(1, nowMs = 5_000L, queue = truncated), + ) + assertIs( + w.stopFor(1, nowMs = 10_000L, queue = truncated), + ) + assertIs( + 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( + 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(next) + assertEquals(1, next.attempt) + } + @Test fun `reset forgets everything`() { val w = RemoteStallWatchdog() diff --git a/android/app/src/test/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClientTest.kt b/android/app/src/test/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClientTest.kt index a76ba348..48919b60 100644 --- a/android/app/src/test/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClientTest.kt +++ b/android/app/src/test/java/com/fabledsword/minstrel/player/output/upnp/AVTransportClientTest.kt @@ -183,6 +183,52 @@ class AVTransportClientTest { } } + @Test + fun `getMediaInfo parses NrTracks and CurrentURI`() = runTest { + server.enqueue( + MockResponse().setBody( + """ + + + + 42 + 0:00:00 + x-rincon-queue:RINCON_ABC#0 + + + """.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( + """ + + + + http://x/y.mp3 + + + """.trimIndent(), + ), + ) + assertEquals(0, client.getMediaInfo().nrTracks) + } + private fun emptyResponse(action: String): MockResponse = MockResponse().setBody( """