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..dfcda283 --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt @@ -0,0 +1,75 @@ +package com.fabledsword.minstrel.diagnostics + +import com.fabledsword.minstrel.player.TransportObservation + +/** + * Decides when a run of renderer transport changes is a *flap* — the renderer + * repeatedly failing to settle — rather than an ordinary track transition. + * + * The operator reports the Sonos "play pause play pause, like someone pressing + * it every half second", usually as a track starts. No diagnostic event could + * see it, so it has been described several times and measured never. This is + * the rule that decides when an episode is worth writing down. + * + * Pure decision state, like [com.fabledsword.minstrel.player.RemoteStallWatchdog]: + * the caller owns the flow and the recording, this only answers "is this an + * episode, and which readings make it up". Keeps the windowing and the + * one-episode-one-summary rule testable without a renderer or a clock. + */ +class TransportFlapDetector( + private val windowMs: Long = FLAP_WINDOW_MS, + private val minChanges: Int = FLAP_MIN_CHANGES, + private val summaryCooldownMs: Long = FLAP_SUMMARY_COOLDOWN_MS, +) { + private val recent = ArrayDeque() + 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) + dropReadingsOlderThan(observation.atElapsedMs) + if (!isEpisode(observation.atElapsedMs)) return null + lastSummaryAtMs = observation.atElapsedMs + return recent.toList() + } + + private fun dropReadingsOlderThan(nowMs: Long) { + while (recent.isNotEmpty() && nowMs - recent.first().atElapsedMs > windowMs) { + recent.removeFirst() + } + } + + /** + * Enough changes packed together, and far enough from the last thing we + * wrote down. The cooldown is what keeps one episode to one summary: a + * sustained fault produces a change every poll, and a summary per reading + * would bury the per-change events underneath them. + */ + private fun isEpisode(nowMs: Long): Boolean { + val since = lastSummaryAtMs + val cooled = since == null || nowMs - since >= summaryCooldownMs + return recent.size >= minChanges && cooled + } + + /** Forget everything — call when the route changes or casting ends. */ + fun reset() { + recent.clear() + lastSummaryAtMs = null + } + + companion object { + // Readings arrive at the 1 Hz poll cadence, and a normal track + // transition is 2-3 changes (PLAYING -> TRANSITIONING -> PLAYING). + // Four inside six seconds is not a track change, and it is not a + // person at the Sonos app either; it is the renderer not settling. + const val FLAP_WINDOW_MS = 6_000L + const val FLAP_MIN_CHANGES = 4 + const val FLAP_SUMMARY_COOLDOWN_MS = 60_000L + } +} 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..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 @@ -48,12 +49,12 @@ import timber.log.Timber * * Drop heuristic: the 1 Hz poll loop is the *sole* arbiter of route * liveness -- [RemotePlayerState.recordPollFailure]'s rolling threshold - * (DROP_THRESHOLD consecutive failures) fires [onDrop]. A failed transport + * (DROP_THRESHOLD consecutive failures) fires [RemoteEvents.onDrop]. A failed transport * command (play/pause/seek/next) does NOT drop on its own: a locked phone's * WiFi power-save can stall a single command's socket I/O for a second or * two while the renderer is perfectly reachable, so commands retry on * transient IO failure and otherwise defer to the poll loop. The factory - * wraps the [onDrop] callback into a SharedFlow consumed by the NowPlaying + * wraps that callback into a SharedFlow consumed by the NowPlaying * surface as a snackbar. * * Queue mode: OutputPickerController loads the full queue into Sonos's @@ -71,10 +72,29 @@ class MinstrelForwardingPlayer( private val remoteState: RemotePlayerState, private val castNetworkLock: CastNetworkLock, private val networkStatus: NetworkStatusController, - private val onDrop: (routeName: String) -> Unit, - private val onStalled: (trackId: String) -> Unit = {}, + private val events: RemoteEvents = RemoteEvents(), ) : ForwardingPlayer(delegate) { + /** + * The ways remote playback reports trouble outward. Grouped rather than + * passed as three more constructor lambdas: they share a lifetime, they + * all end up as flows on [PlayerFactory], and the list grows every time + * the renderer finds a new way to disappoint us. + */ + data class RemoteEvents( + /** A route stopped answering and playback fell back to the phone. */ + val onDrop: (routeName: String) -> Unit = {}, + /** A track could not be got playing again; surfaces to the user. */ + val onStalled: (trackId: String) -> Unit = {}, + /** The renderer's queue is short of ours and needs rebuilding. */ + val onQueueTruncated: () -> Unit = {}, + /** + * A raw poll reading, emitted only when it differs from the previous + * one. Diagnostics-only; see [TransportObservation]. + */ + val onTransport: (TransportObservation) -> Unit = {}, + ) + private val scope = CoroutineScope(SupervisorJob() + Dispatchers.IO) private val handler = Handler(delegate.applicationLooper) private var pollJob: Job? = null @@ -97,6 +117,16 @@ class MinstrelForwardingPlayer( // visibly jumps backwards immediately after a drag, then forwards again. @Volatile private var lastSeekIssuedAtMs: Long = 0L + // Last-read renderer queue length + when we read it. See [queueStateFor]: + // a stopped renderer is polled once a second and its queue does not change + // by itself, so re-asking every tick is pure round-trips. + @Volatile private var cachedNrTracks: Int = 0 + @Volatile private var lastMediaInfoAtMs: Long = 0L + + // Previous raw transport reading, so [TransportObservation]s are emitted + // on change rather than once a second forever. Null until the first poll. + @Volatile private var lastObservedTransport: Pair? = null + // Wake channel for the poll loop. requestImmediatePoll() trySend's a Unit; // pollLoop's select{} races the delay against this channel so the next // pollOnce can fire immediately instead of waiting up to POLL_INTERVAL_MS. @@ -488,17 +518,35 @@ class MinstrelForwardingPlayer( // without this the radio power-saves on a locked screen and the // poll below starves -- see [CastNetworkLock]. castNetworkLock.acquire() - // Pause the wrapped ExoPlayer so we are not playing local audio - // simultaneously with the remote renderer. handler.post targets the - // application looper, so this runs on the same thread that processes - // our override calls -- no race with the pause() override branching - // to SOAP (holder.active is already non-null by the time this post - // fires, but delegate.pause() bypasses the override entirely). - handler.post { delegate.pause() } + // STOP the wrapped ExoPlayer -- not pause. pause() is only + // playWhenReady=false: ExoPlayer's LoadControl keeps loading, so a + // paused-but-prepared player goes on downloading the current track + // (~50s of buffer). During a cast that means the phone pulls the + // same file the renderer is streaming, over the same WiFi, and + // re-arms on every track change via syncLocalCursorToRemote's + // seekTo. At FLAC bitrates that is a second full-rate download + // competing with the speaker for air, starting exactly when a new + // track does. stop() ends the loading; Media3 keeps the media + // items, the current index and the position, so cursor sync and + // the handoff back are unaffected, and getPlaybackState() already + // reports STATE_READY while remote so no external reader sees IDLE. + // + // handler.post targets the application looper, so this runs on the + // same thread that processes our override calls -- no race with the + // pause() override branching to SOAP (holder.active is already + // non-null by the time this post fires, but delegate.stop() + // bypasses the override entirely). + handler.post { delegate.stop() } pollJob = scope.launch { pollLoop(active) } } else { castNetworkLock.release() remoteState.reset() + lastObservedTransport = null + // The delegate was stopped for the cast, so it is IDLE and would + // ignore a play(). Re-prepare it for local playback. Safe when the + // queue is empty, and it does not start playback on its own -- + // playWhenReady is still false until something calls play(). + handler.post { delegate.prepare() } // The next cast starts with a clean attempt budget; a stall on the // route we just left says nothing about the next one. stallWatchdog.reset() @@ -516,7 +564,7 @@ class MinstrelForwardingPlayer( } else if (remoteState.recordPollFailure()) { if (networkStatus.state.value == ServerHealth.Healthy) { Timber.w("UPnP drop threshold tripped for %s", active.routeName) - handler.post { onDrop(active.routeName) } + handler.post { events.onDrop(active.routeName) } return } networkDropSuppressed = suppressDropForNetwork(active, networkDropSuppressed) @@ -594,6 +642,7 @@ class MinstrelForwardingPlayer( } TransportState.TRANSITIONING, TransportState.UNKNOWN -> Unit } + observeTransport(transport, info) checkForStall(active, info.trackUri, transport) notifyRemoteStateChanged() } @@ -613,12 +662,15 @@ class MinstrelForwardingPlayer( transport: TransportInfo, ) { val decision = stallWatchdog.onPoll( - trackUri = trackUri, - state = transport.state, - statusOk = transport.statusOk, - playIntent = remoteState.lastPlayIntent, - positionMs = remoteState.positionMs, - nowMs = SystemClock.elapsedRealtime(), + RemoteStallWatchdog.Poll( + trackUri = trackUri, + state = transport.state, + statusOk = transport.statusOk, + playIntent = remoteState.lastPlayIntent, + positionMs = remoteState.positionMs, + nowMs = SystemClock.elapsedRealtime(), + queue = queueStateFor(active, transport), + ), ) when (decision) { is RemoteStallWatchdog.Decision.Resume -> { @@ -638,6 +690,17 @@ class MinstrelForwardingPlayer( Timber.w(it, "UPnP stall: resume attempt failed on %s", active.routeName) } } + is RemoteStallWatchdog.Decision.RepairQueue -> { + Timber.w( + "UPnP queue truncated on %s: renderer ended at its last track " + + "while %d local tracks remain; repair attempt %d", + active.routeName, delegate.mediaItemCount, decision.attempt, + ) + // The renderer isn't broken -- it played everything it was + // given. Rebuilding the queue is the fix; the controller owns + // queue loading, so ask it rather than duplicating that here. + handler.post { events.onQueueTruncated() } + } RemoteStallWatchdog.Decision.GiveUp -> { Timber.w( "UPnP stall on %s: giving up after repeated resume attempts", @@ -645,12 +708,80 @@ class MinstrelForwardingPlayer( ) // Tell the user and the admin inbox. Silence here would be the // original bug: playback simply ends and nobody finds out. - trackIdFromStreamUri(trackUri)?.let { handler.post { onStalled(it) } } + trackIdFromStreamUri(trackUri)?.let { handler.post { events.onStalled(it) } } } RemoteStallWatchdog.Decision.None -> Unit } } + /** + * Publish this poll's raw transport reading if it differs from the last. + * + * Change-gated on purpose: steady playback is one reading repeated once a + * second, which is worth nothing and would fill the ring buffer. What is + * worth capturing is the renderer LEAVING a state — which during normal + * playback happens a couple of times per track, and during the fault the + * operator describes should happen repeatedly within a few seconds. + */ + private fun observeTransport(transport: TransportInfo, info: PositionInfo) { + val key = transport.state to transport.statusOk + if (key == lastObservedTransport) return + lastObservedTransport = key + events.onTransport( + TransportObservation( + state = transport.state.name, + statusOk = transport.statusOk, + trackNumber = info.track, + positionMs = info.relTimeMs, + playIntent = remoteState.lastPlayIntent, + atElapsedMs = SystemClock.elapsedRealtime(), + ), + ) + } + + /** + * How the renderer's queue compares to ours, for [RemoteStallWatchdog]. + * + * Only asked when the transport is actually stopped or reporting an error: + * while it plays, the answer changes nothing and GetMediaInfo would be a + * third SOAP round-trip every second. Even then the result is cached for + * [MEDIA_INFO_TTL_MS], because a stopped renderer gets polled once a + * second and its queue length does not change on its own. + * + * A renderer that reports NrTracks=0 is telling us nothing usable (some + * don't implement it) -- that reads as UNKNOWN, never as "empty queue", + * so an unhelpful renderer keeps the old resume-and-seek behaviour rather + * than being told its queue is broken. + */ + @Suppress("ReturnCount") // one early return per verdict reads better than nesting + private suspend fun queueStateFor( + active: ActiveUpnp, + transport: TransportInfo, + ): RemoteStallWatchdog.QueueState { + val stalled = transport.state == TransportState.STOPPED || !transport.statusOk + if (!stalled) return RemoteStallWatchdog.QueueState.UNKNOWN + + val now = SystemClock.elapsedRealtime() + if (now - lastMediaInfoAtMs > MEDIA_INFO_TTL_MS) { + lastMediaInfoAtMs = now + cachedNrTracks = runCatching { active.avTransport.getMediaInfo().nrTracks } + .onFailure { Timber.w(it, "UPnP GetMediaInfo failed on %s", active.routeName) } + .getOrDefault(0) + } + val nrTracks = cachedNrTracks + val rendererTrack = remoteState.trackNumber + if (nrTracks <= 0 || rendererTrack <= 0) return RemoteStallWatchdog.QueueState.UNKNOWN + if (rendererTrack < nrTracks) return RemoteStallWatchdog.QueueState.HAS_MORE + + // On its last track. Whether that is a problem depends entirely on + // whether we have tracks it never received. + return if (delegate.mediaItemCount > nrTracks) { + RemoteStallWatchdog.QueueState.TRUNCATED + } else { + RemoteStallWatchdog.QueueState.COMPLETE + } + } + /** * Align the paused local delegate cursor to the track the renderer is * actually playing, so the un-overridden current-item getters @@ -743,6 +874,10 @@ class MinstrelForwardingPlayer( const val POLL_INTERVAL_MS = 1_000L const val NON_PLAYING_CONFIRM = 2 const val SEEK_ACK_WINDOW_MS = 2_000L + // How long a GetMediaInfo queue-length reading stays good for. The + // watchdog needs three agreeing polls (~3s) before it acts, so one + // read comfortably covers a decision without asking every tick. + const val MEDIA_INFO_TTL_MS = 5_000L // Safety upper bound on how long the polling tick will wait for // Sonos to ack a user transport. The common case clears event-driven // when Sonos's reported Track matches the wrapped player; this only 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 745e6b8c..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 @@ -84,6 +84,29 @@ 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() + + // 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( @@ -92,8 +115,12 @@ class PlayerFactory @Inject constructor( remoteState = remoteState, castNetworkLock = CastNetworkLock(context), networkStatus = serverHealth, - onDrop = { name -> emitDrop(name) }, - onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) }, + events = MinstrelForwardingPlayer.RemoteEvents( + onDrop = { name -> emitDrop(name) }, + onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) }, + onQueueTruncated = { queueRepairInternal.tryEmit(Unit) }, + onTransport = { transportInternal.tryEmit(it) }, + ), ) } @@ -146,6 +173,12 @@ class PlayerFactory @Inject constructor( .build(), ) + private companion object { + // Enough readings to hold a whole flap episode plus the normal + // transitions around it; the detector's window is only a few seconds. + const val TRANSPORT_EVENT_BUFFER = 32 + } + private fun emitDrop(routeName: String) { dropEventsInternal.tryEmit(routeName) } 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/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/main/java/com/fabledsword/minstrel/player/output/OutputPickerController.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/output/OutputPickerController.kt index 80d9a6b1..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, @@ -173,6 +171,7 @@ class OutputPickerController @Inject constructor( playerFactory.dropEvents.collect { handleRemoteDrop() } } scope.launch { observeQueueChangesForSonosResync() } + scope.launch { observeQueueRepairRequests() } scope.launch { observeIdleRevertWhileUpnp() } scope.launch { observeSelectedRouteDisappearance() } } @@ -255,7 +254,7 @@ class OutputPickerController @Inject constructor( * setMediaItems override clears holder.active + sets target so the * imminent play() call drops (drops via isLoadingUpnp() = true). Then * this collector observes the uiState.queue change and re-runs - * loadQueueOnSonos to push the new tracks to Sonos. + * SonosQueueLoader.load to push the new tracks to Sonos. * * Discrimination: selectUpnp's initial-load path doesn't change * uiState.queue (the queue was already populated before route @@ -286,6 +285,71 @@ class OutputPickerController @Inject constructor( } } + /** + * Rebuild the renderer's queue when playback stopped because the renderer + * ran off the end of a queue shorter than ours. + * + * [SonosQueueLoader] tolerates individual AddURIToQueue failures and + * gives up appending after a few consecutive ones + * -- Sonos rate-limits burst adds. Until this existed that left a short + * queue on the renderer and nothing to notice it: the renderer played what + * it had and stopped, and the app went on believing there were forty + * tracks left. [MinstrelForwardingPlayer] now compares GetMediaInfo's + * NrTracks against the local queue and asks for this. + * + * A full reload, not an incremental diff: the renderer's copy is known to + * be wrong, and the diff path reasons from what we *think* it holds, which + * is exactly the assumption that failed. The load re-seeks to the + * current track and plays, so recovery lands where the listener was. + */ + private suspend fun observeQueueRepairRequests() { + playerFactory.queueRepairEvents.collect { + val routeId = selectedUpnpRouteIdInternal.value + ?: activeUpnpHolder.active.value?.routeId + if (routeId == null) { + Timber.w("Sonos queue repair skipped: no UPnP route selected") + return@collect + } + val state = playerController.uiState.value + if (state.queue.isEmpty()) { + Timber.w("Sonos queue repair skipped: local queue is empty") + return@collect + } + // Resume on the track AFTER the current one. The renderer stopped + // because it finished the last track it had; the local cursor is + // synced to that track, so reloading at it would replay something + // the listener just heard. The next one is what they never got. + val resumeAt = (state.queueIndex + 1).coerceAtMost(state.queue.size - 1) + repairSonosQueue(routeId, state.queue, resumeAt) + } + } + + private suspend fun repairSonosQueue( + routeId: String, + queue: List, + currentIndex: Int, + ) = selectUpnpMutex.withLock { + val upnpRoute = upnpDiscovery.routes.value.firstOrNull { it.id == routeId } + val transport = upnpDiscovery.transportFor(routeId) + if (upnpRoute == null || transport == null) { + Timber.w("Sonos queue repair: route or transport gone for %s", routeId) + return@withLock + } + val outputRoute = OutputRoute.fromUpnpRoute(upnpRoute) + Timber.w( + "Sonos queue repair: reloading %d tracks on %s (resuming at index %d)", + queue.size, outputRoute.name, currentIndex, + ) + runCatching { + sonosQueue.load(transport, outputRoute, queue, currentIndex) + }.onFailure { e -> + // Leave the route active: the renderer is reachable enough to have + // told us its queue length, so dropping to local would be a harsher + // remedy than letting the next stall re-decide. + Timber.w(e, "Sonos queue repair failed on %s", outputRoute.name) + } + } + /** * Bring Sonos's native queue back in sync with the local queue after a * mutation. Tries an incremental SOAP diff first (RemoveTrackRangeFromQueue @@ -313,7 +377,7 @@ class OutputPickerController @Inject constructor( return@withLock } val handledIncrementally = runCatching { - tryIncrementalResync(transport, oldIds, newQueue) + sonosQueue.tryIncrementalResync(transport, oldIds, newQueue) }.getOrElse { e -> Timber.w(e, "Sonos incremental resync errored; falling back to full reload") false @@ -337,7 +401,7 @@ class OutputPickerController @Inject constructor( val rendering = renderingClientFor(routeId) Timber.w("Sonos resync: full reload of %d tracks on %s", newQueue.size, outputRoute.name) runCatching { - loadQueueOnSonos(transport, outputRoute, newQueue, newCurrentIndex) + sonosQueue.load(transport, outputRoute, newQueue, newCurrentIndex) activeUpnpHolder.set( ActiveUpnp( routeId = routeId, @@ -354,98 +418,6 @@ class OutputPickerController @Inject constructor( } } - /** - * Diff-based incremental Sonos queue sync. Returns true when the new - * queue can be produced from the old one with a remove-then-insert at - * the same middle slice -- the common-prefix and common-suffix portions - * stay untouched, and the current Sonos track must lie in the preserved - * prefix (otherwise the diff would orphan playback). Returns false to - * signal the caller to fall back to a full reload. - */ - private suspend fun tryIncrementalResync( - transport: AVTransportClient, - oldIds: List, - 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 @@ -539,7 +511,7 @@ class OutputPickerController @Inject constructor( * 1. Pause local so the user doesn't keep hearing local audio. * 2. Set target early so ForwardingPlayer drops transport taps * while the 17-second queue load is in progress. - * 3. Wire active LAST (after loadQueueOnSonos) so SOAP commands + * 3. Wire active LAST (after the queue load) so SOAP commands * are never routed to a half-loaded Sonos queue. */ private suspend fun selectUpnp(route: OutputRoute) = selectUpnpMutex.withLock { @@ -580,7 +552,7 @@ class OutputPickerController @Inject constructor( // taps don't hit Sonos's stale state from a prior session. activeUpnpHolder.setTarget(effectiveRoute.id) runCatching { - loadQueueOnSonos(transport, effectiveRoute, uiState.queue, uiState.queueIndex) + sonosQueue.load(transport, effectiveRoute, uiState.queue, uiState.queueIndex) // Wire active LAST -- SOAP path is now safe to use. activeUpnpHolder.set( ActiveUpnp( @@ -697,108 +669,6 @@ class OutputPickerController @Inject constructor( return if (i >= 0) segments.getOrNull(i + 1) else null } - private suspend fun loadQueueOnSonos( - transport: AVTransportClient, - route: OutputRoute, - queue: List, - currentIndex: Int, - ) { - Timber.w("UPnP select: clear queue on %s", route.name) - transport.removeAllTracksFromQueue() - val initialEnd = (currentIndex + 1).coerceAtMost(queue.size) - val initialBatch = queue.subList(0, initialEnd) - Timber.w( - "UPnP select: add %d initial tracks (currentIndex=%d, totalQueue=%d)", - initialBatch.size, currentIndex, queue.size, - ) - initialBatch.forEachIndexed { idx, ref -> - val token = streamTokens.mint(ref.id) - transport.addURIToQueue( - uri = token.url, - mime = token.mime, - title = token.title, - enqueuedURIPosition = idx + 1, - ) - } - val coordinatorUdn = route.id.bareUdn() - val queueUri = "x-rincon-queue:$coordinatorUdn#0" - Timber.w("UPnP select: SetAVTransportURI %s", queueUri) - transport.setAVTransportURI(queueUri, "") - Timber.w("UPnP select: Seek to track %d", currentIndex + 1) - transport.seekToTrack(currentIndex + 1) - Timber.w("UPnP select: Play") - transport.play() - Timber.w("UPnP select: initial done; backgrounding remainder") - val remaining = queue.drop(initialEnd) - if (remaining.isNotEmpty()) { - scope.launch { extendQueueOnSonos(transport, route, remaining, initialEnd) } - } - } - - /** - * Background-append tracks after activation. Runs concurrently with - * Sonos playback. Cancels if the user disconnects from this route - * (active.routeId changes or becomes null). Tolerates individual - * AddURIToQueue failures — log and continue so some tracks loaded - * is better than zero tracks loaded. - */ - private suspend fun extendQueueOnSonos( - transport: AVTransportClient, - route: OutputRoute, - tracks: List, - startPosition: Int, - ) { - Timber.w( - "UPnP extend: appending %d tracks starting at position %d", - tracks.size, startPosition + 1, - ) - var consecutiveFailures = 0 - var succeeded = 0 - var aborted = false - for ((i, ref) in tracks.withIndex()) { - if (aborted) break - if (activeUpnpHolder.active.value?.routeId != route.id) { - Timber.w("UPnP extend: cancelled at offset %d (route changed)", i) - aborted = true - } else { - val outcome = runCatching { - val token = streamTokens.mint(ref.id) - transport.addURIToQueue( - uri = token.url, - mime = token.mime, - title = token.title, - enqueuedURIPosition = startPosition + i + 1, - ) - } - if (outcome.isSuccess) { - consecutiveFailures = 0 - succeeded += 1 - // Throttle the burst so we don't tickle Sonos's burst-add - // rejection -- logcat 2026-06-04 showed 33 consecutive - // failures clustered at ~10ms intervals once offset 39 was - // reached, which looks like a rate-limit kicking in. The - // delay is small enough that extending 100 tracks adds - // only ~5s to background work that's already async. - delay(EXTEND_THROTTLE_MS) - } else { - consecutiveFailures += 1 - val e = outcome.exceptionOrNull() - val detail = (e as? SoapFaultException)?.let { - "code=${it.code} desc=${it.description}" - } ?: e?.message - Timber.w(e, "UPnP extend: append failed at offset %d -- %s", i, detail) - if (consecutiveFailures >= EXTEND_ABORT_AFTER_FAILURES) { - Timber.w( - "UPnP extend: aborting after %d consecutive failures", - consecutiveFailures, - ) - aborted = true - } - } - } - } - Timber.w("UPnP extend: done (%d / %d appended)", succeeded, tracks.size) - } private fun renderingClientFor(routeId: String): RenderingControlClient? { val rcUrl = upnpDiscovery.routes.value @@ -830,9 +700,6 @@ class OutputPickerController @Inject constructor( } private companion object { - const val EXTEND_ABORT_AFTER_FAILURES = 3 - const val EXTEND_THROTTLE_MS = 50L - // 5 minutes of continuous non-playing on a UPnP route before we // revert to the phone speaker, so a stale Sonos selection can't make // a later "tap play" do nothing. 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 + } +} 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/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) + } +} 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( """