From 8e21bce103b585e55e61692569033830dae5b8b6 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 17 Aug 2026 22:29:54 -0400 Subject: [PATCH 1/4] =?UTF-8?q?fix(player):=20verify=20the=20Sonos=20queue?= =?UTF-8?q?=20actually=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( """ From e87516bbe4f6ee167f0cd5fbbd85c53a81685036 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 17 Aug 2026 22:35:53 -0400 Subject: [PATCH 2/4] =?UTF-8?q?refactor(player):=20split=20Sonos=20queue?= =?UTF-8?q?=20loading=20out=20of=20the=20picker=20=E2=80=94=20#2728?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit detekt flagged OutputPickerController as LargeClass once the verify path landed. Extracting rather than suppressing: how the renderer's queue is shaped is a different concern from which route is selected, and it had grown big enough to hide a bug — every write in here is a SOAP call that can fail on its own, and nothing ever read the result back. SonosQueueLoader now owns load / extend / verify / append and the incremental diff. The picker keeps route selection and asks it for queue work. No behaviour change. --- .../player/output/OutputPickerController.kt | 299 +---------------- .../player/output/SonosQueueLoader.kt | 316 ++++++++++++++++++ 2 files changed, 327 insertions(+), 288 deletions(-) create mode 100644 android/app/src/main/java/com/fabledsword/minstrel/player/output/SonosQueueLoader.kt 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 57b2860c..42a423b2 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 @@ -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, @@ -256,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 @@ -291,8 +289,8 @@ 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 + * [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 @@ -301,7 +299,7 @@ class OutputPickerController @Inject constructor( * * 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 + * 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() { @@ -343,7 +341,7 @@ class OutputPickerController @Inject constructor( queue.size, outputRoute.name, currentIndex, ) runCatching { - loadQueueOnSonos(transport, outputRoute, queue, currentIndex) + 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 @@ -379,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 @@ -403,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, @@ -420,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, - newQueue: List, - ): 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, - 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, b: List): 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, b: List): 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 @@ -605,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 { @@ -646,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( @@ -763,179 +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, - 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, - 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, - ) { - 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 - 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 - } private fun renderingClientFor(routeId: String): RenderingControlClient? { val rcUrl = upnpDiscovery.routes.value @@ -967,16 +700,6 @@ class OutputPickerController @Inject constructor( } private companion object { - 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/SonosQueueLoader.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/output/SonosQueueLoader.kt new file mode 100644 index 00000000..950b5024 --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/output/SonosQueueLoader.kt @@ -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, + 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, + 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, + ) { + 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 + 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, + newQueue: List, + ): 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, + 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, b: List): 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, b: List): 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 + } +} From 72c0e96f92cb7b08951582823a23ac8d87b85a2c Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 18 Aug 2026 09:55:41 -0400 Subject: [PATCH 3/4] fix(player): stop the local player during a cast; capture transport flap Two changes for the Sonos stutter the operator describes as rapid play-pause-play at the start of a track. The measurable one: 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 45s. A few seconds of oscillation that changes no index fell through all three, which is why the symptom has been described repeatedly and measured never. The poll loop now publishes raw GetTransportInfo readings on change, and TransportFlapDetector turns a burst of them into one summary event carrying the sequence alongside local-vs-Sonos track and position -- enough to tell a cursor disagreement from the renderer rebuffering. It samples at the 1Hz poll cadence, so a faster oscillation lands aliased; that still answers whether the renderer is leaving PLAYING, which is the open question. The suspect one: during a cast the wrapped ExoPlayer was paused, not stopped. pause() is only playWhenReady=false -- LoadControl keeps loading, so the phone went on downloading the track the renderer was streaming, over the same WiFi, re-arming at every track change via syncLocalCursorToRemote's seekTo. At FLAC bitrates that is a second full-rate download competing with the speaker, beginning exactly when a new track does. stop() ends it; Media3 keeps media items, index and position, and getPlaybackState() already reports STATE_READY while remote, so cursor sync and handoff are unaffected. The route teardown re-prepares for local playback. Whether that download is the cause is unproven -- hence the instrument landing alongside it rather than after it. --- .../diagnostics/DiagnosticsReporter.kt | 63 +++++++++ .../diagnostics/TransportFlapDetector.kt | 65 +++++++++ .../player/MinstrelForwardingPlayer.kt | 68 +++++++++- .../minstrel/player/PlayerController.kt | 7 + .../minstrel/player/PlayerFactory.kt | 19 +++ .../minstrel/player/TransportObservation.kt | 38 ++++++ .../diagnostics/TransportFlapDetectorTest.kt | 128 ++++++++++++++++++ 7 files changed, 381 insertions(+), 7 deletions(-) create mode 100644 android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt create mode 100644 android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt create mode 100644 android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt diff --git a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt index 142f5a2b..4ce6f4f0 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt @@ -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) { + 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. diff --git a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt new file mode 100644 index 00000000..2297914a --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt @@ -0,0 +1,65 @@ +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() + 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? { + recent.addLast(observation) + while (recent.isNotEmpty() && + observation.atElapsedMs - recent.first().atElapsedMs > windowMs + ) { + recent.removeFirst() + } + if (recent.size < minChanges) return null + // One episode, one summary. A sustained fault would otherwise emit a + // summary per reading and bury the per-change events underneath them. + val since = lastSummaryAtMs + if (since != null && observation.atElapsedMs - since < summaryCooldownMs) return null + lastSummaryAtMs = observation.atElapsedMs + return recent.toList() + } + + /** 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 + } +} 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 fcb55d3a..1556bb42 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 @@ -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 @@ -87,6 +88,11 @@ class MinstrelForwardingPlayer( 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) @@ -117,6 +123,10 @@ class MinstrelForwardingPlayer( @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? = 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. @@ -508,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() @@ -614,6 +642,7 @@ class MinstrelForwardingPlayer( } TransportState.TRANSITIONING, TransportState.UNKNOWN -> Unit } + observeTransport(transport, info) checkForStall(active, info.trackUri, transport) notifyRemoteStateChanged() } @@ -685,6 +714,31 @@ class MinstrelForwardingPlayer( } } + /** + * 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]. * diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt index 631b0ad5..44c1b01c 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt @@ -77,6 +77,13 @@ class PlayerController @Inject constructor( * during UPnP playback shows "Disconnected from " to the user. */ val dropEvents: SharedFlow = 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 = playerFactory.transportEvents private val sessionToken = SessionToken(context, ComponentName(context, MinstrelPlayerService::class.java)) 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 05bda717..741c024c 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 @@ -95,6 +95,18 @@ class PlayerFactory @Inject constructor( ) val queueRepairEvents: SharedFlow = 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( + replay = 0, + extraBufferCapacity = TRANSPORT_EVENT_BUFFER, + onBufferOverflow = BufferOverflow.DROP_OLDEST, + ) + val transportEvents: SharedFlow = transportInternal.asSharedFlow() + fun build(): Player { val exo = buildExoPlayer() return MinstrelForwardingPlayer( @@ -107,6 +119,7 @@ class PlayerFactory @Inject constructor( onDrop = { name -> emitDrop(name) }, onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) }, onQueueTruncated = { queueRepairInternal.tryEmit(Unit) }, + onTransport = { transportInternal.tryEmit(it) }, ), ) } @@ -160,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) } diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt new file mode 100644 index 00000000..f816efac --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt @@ -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, +) diff --git a/android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt b/android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt new file mode 100644 index 00000000..490e4615 --- /dev/null +++ b/android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt @@ -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) + } +} From 0103953953933faddce48935b53f3e3e39a2c28e Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 18 Aug 2026 10:00:43 -0400 Subject: [PATCH 4/4] refactor(diagnostics): split the flap window and episode rule apart detekt ReturnCount. Extracting the pruning and the is-this-an-episode predicate reads better than suppressing it, and the cooldown rule now has a name and a docstring of its own. --- .../diagnostics/TransportFlapDetector.kt | 30 ++++++++++++------- 1 file changed, 20 insertions(+), 10 deletions(-) diff --git a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt index 2297914a..dfcda283 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt @@ -33,20 +33,30 @@ class TransportFlapDetector( */ fun onChange(observation: TransportObservation): List? { recent.addLast(observation) - while (recent.isNotEmpty() && - observation.atElapsedMs - recent.first().atElapsedMs > windowMs - ) { - recent.removeFirst() - } - if (recent.size < minChanges) return null - // One episode, one summary. A sustained fault would otherwise emit a - // summary per reading and bury the per-change events underneath them. - val since = lastSummaryAtMs - if (since != null && observation.atElapsedMs - since < summaryCooldownMs) return null + 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()