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 be14cc46..7bc0bb40 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 @@ -15,6 +15,7 @@ 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.SoapFaultException +import com.fabledsword.minstrel.player.output.upnp.TransportInfo import com.fabledsword.minstrel.player.output.upnp.TransportState import java.io.IOException import kotlin.math.abs @@ -71,12 +72,18 @@ class MinstrelForwardingPlayer( private val castNetworkLock: CastNetworkLock, private val networkStatus: NetworkStatusController, private val onDrop: (routeName: String) -> Unit, + private val onStalled: (trackId: String) -> Unit = {}, ) : ForwardingPlayer(delegate) { private val scope = CoroutineScope(SupervisorJob() + Dispatchers.IO) private val handler = Handler(delegate.applicationLooper) private var pollJob: Job? = null + // Watches for the renderer stopping without being asked to. A UPnP + // renderer streams on its own, so a stream that dies looks like silence + // and nothing else in the app would notice -- see [RemoteStallWatchdog]. + private val stallWatchdog = RemoteStallWatchdog() + // Tracks consecutive non-PLAYING poll observations so a single transient // PAUSED_PLAYBACK / STOPPED tick during a Sonos track transition does not // flip the play/pause button. Manual pause still feels instant because it @@ -492,6 +499,9 @@ class MinstrelForwardingPlayer( } else { castNetworkLock.release() remoteState.reset() + // 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() } } @@ -584,9 +594,63 @@ class MinstrelForwardingPlayer( } TransportState.TRANSITIONING, TransportState.UNKNOWN -> Unit } + checkForStall(active, info.trackUri, transport) notifyRemoteStateChanged() } + /** + * Ask the watchdog what to make of this poll, and act on its answer. + * + * Recovery re-issues Play and then seeks back to the last position the + * renderer was observed playing, so a stream that died 90 seconds into a + * track resumes near there rather than restarting it. The seek is + * best-effort and deliberately after the play: a renderer that refuses + * the seek is still better off playing from zero than silent. + */ + private suspend fun checkForStall( + active: ActiveUpnp, + trackUri: String, + transport: TransportInfo, + ) { + val decision = stallWatchdog.onPoll( + trackUri = trackUri, + state = transport.state, + statusOk = transport.statusOk, + playIntent = remoteState.lastPlayIntent, + positionMs = remoteState.positionMs, + nowMs = SystemClock.elapsedRealtime(), + ) + when (decision) { + is RemoteStallWatchdog.Decision.Resume -> { + Timber.w( + "UPnP stall on %s: renderer stopped unasked (status_ok=%b), " + + "resume attempt %d at %dms", + active.routeName, transport.statusOk, decision.attempt, decision.resumeAtMs, + ) + runCatching { + retryTransport { active.avTransport.play() } + if (decision.resumeAtMs > 0L) { + retryTransport { active.avTransport.seek(decision.resumeAtMs) } + } + }.onFailure { + // Leave the streak alone: a failed recovery is more + // evidence of a stall, and the next poll re-decides. + Timber.w(it, "UPnP stall: resume attempt failed on %s", active.routeName) + } + } + RemoteStallWatchdog.Decision.GiveUp -> { + Timber.w( + "UPnP stall on %s: giving up after repeated resume attempts", + active.routeName, + ) + // 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) } } + } + RemoteStallWatchdog.Decision.None -> Unit + } + } + /** * Align the paused local delegate cursor to the track the renderer is * actually playing, so the un-overridden current-item getters 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 0a4222b6..28a8481c 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 @@ -128,6 +128,28 @@ class PlayerController @Inject constructor( */ private var queueRefs: List = emptyList() + init { + // A remote stall that survived the watchdog's retries is a playback + // failure like any other: the user gets the snackbar and the operator + // gets an admin-inbox row, via the same reporter that handles dead + // files. Without this the session just ends in silence -- the exact + // failure the watchdog exists to surface. + scope.launch { + playerFactory.stallEvents.collect { trackId -> + val title = queueRefs.firstOrNull { it.id == trackId }?.title + ?.takeIf { it.isNotEmpty() } ?: "Track" + playbackErrorEventsChannel.trySend( + PlaybackErrorEvent( + trackId = trackId, + kind = "stalled", + title = title, + detail = "remote renderer stopped and would not resume", + ), + ) + } + } + } + /** * Completes when [mediaController] is non-null and the listener has * been attached. Used by [awaitReady] so cold-boot callers like 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 7c3a2cad..745e6b8c 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 @@ -75,6 +75,15 @@ class PlayerFactory @Inject constructor( ) val dropEvents: SharedFlow = dropEventsInternal.asSharedFlow() + // Track ids whose remote playback stalled and could not be resumed. Same + // buffering rationale as dropEvents: a burst is one problem, not N. + private val stallEventsInternal = MutableSharedFlow( + replay = 0, + extraBufferCapacity = 1, + onBufferOverflow = BufferOverflow.DROP_OLDEST, + ) + val stallEvents: SharedFlow = stallEventsInternal.asSharedFlow() + fun build(): Player { val exo = buildExoPlayer() return MinstrelForwardingPlayer( @@ -84,6 +93,7 @@ class PlayerFactory @Inject constructor( castNetworkLock = CastNetworkLock(context), networkStatus = serverHealth, onDrop = { name -> emitDrop(name) }, + onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) }, ) } 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 new file mode 100644 index 00000000..ed993480 --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/RemoteStallWatchdog.kt @@ -0,0 +1,159 @@ +package com.fabledsword.minstrel.player + +import com.fabledsword.minstrel.player.output.upnp.TransportState + +/** + * Notices when a UPnP renderer has stopped playing without being asked, and + * decides whether to try getting it going again. + * + * The gap this closes (diagnostics 2026-08-16): a Sonos playing from the + * server stopped by itself mid-track while the phone was in Doze. The poll + * loop was frozen, so nothing saw it; when the screen came back on the app + * faithfully reported "queue track 10, position 113s, not playing" and then + * sat there. Playback was over and no part of the app considered that a + * problem. A renderer streams autonomously, which is exactly why a failed + * stream is invisible without something watching for it. + * + * Deliberately conservative about what counts as a stall: + * + * - Only STOPPED (or a transport reporting an error) triggers recovery. + * PAUSED is left alone: the likely cause is a person pausing from the + * Sonos app or a wall controller, and fighting them for the transport is + * obnoxious. A stream that dies stops, it does not pause. + * - Only when the operator's last intent was to play. A stop we asked for + * is not a stall. + * - Only after [STALL_CONFIRM_POLLS] consecutive polls agree, so a single + * reading during a track change (Sonos passes through STOPPED and + * TRANSITIONING between queue items) never trips it. + * - At most [MAX_RESUME_ATTEMPTS] per track, spaced by + * [RETRY_SPACING_MS]. A genuinely unplayable file must not become an + * infinite retry loop against the renderer. + * + * 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 + * without a renderer. + */ +class RemoteStallWatchdog { + + sealed interface Decision { + /** Nothing to do. */ + data object None : Decision + + /** + * Ask the renderer to play again. [resumeAtMs] is the last position + * observed while it was actually playing, so the caller can seek back + * to roughly where the listener was rather than restarting the track. + */ + data class Resume(val attempt: Int, val resumeAtMs: Long) : Decision + + /** Attempts are exhausted. Report it and stop trying for this track. */ + data object GiveUp : Decision + } + + private var trackKey: String = "" + private var lastPlayingPositionMs: Long = 0L + private var stoppedStreak: Int = 0 + private var attempts: Int = 0 + private var lastAttemptAtMs: Long = 0L + 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. + */ + @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) { + // New track: a fresh attempt budget, and no inherited stall state. + trackKey = trackUri + resetStall() + attempts = 0 + gaveUp = false + lastPlayingPositionMs = 0L + } + + if (!playIntent) { + // Stopped because we asked. Not a stall, and the next genuine one + // should start from a clean budget. + resetStall() + attempts = 0 + gaveUp = false + return Decision.None + } + + if (state == TransportState.PLAYING && statusOk) { + lastPlayingPositionMs = 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 + // the full set of attempts rather than the remainder. + attempts = 0 + return Decision.None + } + + val stalled = state == TransportState.STOPPED || !statusOk + if (!stalled) { + // PAUSED (someone else's doing) or TRANSITIONING/UNKNOWN (in + // flight). Neither is a stall; drop the streak so a mid-track + // transition doesn't accumulate toward one. + resetStall() + return Decision.None + } + + stoppedStreak += 1 + if (stoppedStreak < STALL_CONFIRM_POLLS) return Decision.None + if (gaveUp) return Decision.None + + if (attempts >= MAX_RESUME_ATTEMPTS) { + gaveUp = true + return Decision.GiveUp + } + if (attempts > 0 && nowMs - lastAttemptAtMs < RETRY_SPACING_MS) return Decision.None + + attempts += 1 + lastAttemptAtMs = nowMs + return Decision.Resume(attempt = attempts, resumeAtMs = lastPlayingPositionMs) + } + + /** Forget everything — call when the route changes or playback is torn down. */ + fun reset() { + trackKey = "" + lastPlayingPositionMs = 0L + resetStall() + attempts = 0 + lastAttemptAtMs = 0L + gaveUp = false + } + + private fun resetStall() { + stoppedStreak = 0 + } + + private companion object { + // At the 1s poll cadence this is ~3s of agreement. Sonos passes + // through STOPPED between queue items, so one or two readings mean + // nothing on their own. + const val STALL_CONFIRM_POLLS = 3 + + // Three tries at ~5s spacing covers a server blip or a dropped + // connection without hammering a renderer whose file is simply bad. + const val MAX_RESUME_ATTEMPTS = 3 + const val RETRY_SPACING_MS = 5_000L + } +} 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 0d27a4f2..6670db0c 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 @@ -225,7 +225,14 @@ class AVTransportClient( "TRANSITIONING" -> TransportState.TRANSITIONING else -> TransportState.UNKNOWN } - return TransportInfo(state) + // CurrentTransportStatus is the renderer's own verdict on whether it is + // healthy, and it is the one unambiguous way to tell "the stream died" + // from "somebody pressed stop" — both of which land in STOPPED. The + // spec defines OK and ERROR_OCCURRED; anything unrecognised (or absent, + // which some renderers do) is read as OK so a quiet device is never + // treated as a broken one. + val statusOk = result["CurrentTransportStatus"]?.let { it != "ERROR_OCCURRED" } ?: true + return TransportInfo(state, statusOk) } private fun buildDidlLite(uri: String, mime: String, title: String): String { @@ -293,4 +300,9 @@ data class PositionInfo( enum class TransportState { PLAYING, PAUSED, STOPPED, TRANSITIONING, UNKNOWN } -data class TransportInfo(val state: TransportState) +/** + * [statusOk] is CurrentTransportStatus, defaulted true so the many call sites + * that only care about [state] read unchanged and an older/quieter renderer is + * never mistaken for a failing one. + */ +data class TransportInfo(val state: TransportState, val statusOk: Boolean = true) 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 new file mode 100644 index 00000000..144db35c --- /dev/null +++ b/android/app/src/test/java/com/fabledsword/minstrel/player/RemoteStallWatchdogTest.kt @@ -0,0 +1,187 @@ +package com.fabledsword.minstrel.player + +import com.fabledsword.minstrel.player.output.upnp.TransportState +import org.junit.jupiter.api.Test +import kotlin.test.assertEquals +import kotlin.test.assertIs +import kotlin.test.assertTrue + +class RemoteStallWatchdogTest { + + private val uri = "http://server/api/tracks/t-1/stream.flac" + private val other = "http://server/api/tracks/t-2/stream.flac" + + /** Feed one poll, defaulting everything to "playing normally". */ + private fun RemoteStallWatchdog.poll( + trackUri: String = uri, + state: TransportState = TransportState.PLAYING, + statusOk: Boolean = true, + playIntent: Boolean = true, + positionMs: Long = 0L, + nowMs: Long = 0L, + ) = onPoll(trackUri, state, statusOk, playIntent, positionMs, nowMs) + + /** Drive [n] stopped polls and return the last decision. */ + private fun RemoteStallWatchdog.stopFor( + n: Int, + nowMs: Long = 0L, + ): RemoteStallWatchdog.Decision { + var last: RemoteStallWatchdog.Decision = RemoteStallWatchdog.Decision.None + repeat(n) { last = poll(state = TransportState.STOPPED, nowMs = nowMs) } + return last + } + + @Test + fun `playing normally asks for nothing`() { + val w = RemoteStallWatchdog() + repeat(10) { assertIs(w.poll(positionMs = it * 1000L)) } + } + + @Test + fun `a stop we asked for is not a stall`() { + val w = RemoteStallWatchdog() + repeat(10) { + assertIs( + w.poll(state = TransportState.STOPPED, playIntent = false), + ) + } + } + + /** + * Sonos passes through STOPPED between queue items. One or two readings + * must never trigger a resume or every track change would fight itself. + */ + @Test + fun `a brief stop during a track transition is ignored`() { + val w = RemoteStallWatchdog() + assertIs(w.stopFor(2)) + } + + @Test + fun `a sustained unrequested stop asks for a resume`() { + val w = RemoteStallWatchdog() + val decision = w.stopFor(3) + assertIs(decision) + assertEquals(1, decision.attempt) + } + + /** The point of the resume: come back where the listener was. */ + @Test + fun `resume carries the last position seen while playing`() { + val w = RemoteStallWatchdog() + w.poll(state = TransportState.PLAYING, positionMs = 113_000L) + val decision = w.stopFor(3) + assertIs(decision) + assertEquals(113_000L, decision.resumeAtMs) + } + + /** + * Someone pausing from the Sonos app or a wall controller owns the + * transport. Grabbing it back would be a fight the user always loses. + */ + @Test + fun `a pause from elsewhere is left alone`() { + val w = RemoteStallWatchdog() + repeat(10) { + assertIs(w.poll(state = TransportState.PAUSED)) + } + } + + @Test + fun `transitioning is not treated as a stall`() { + val w = RemoteStallWatchdog() + repeat(10) { + assertIs( + w.poll(state = TransportState.TRANSITIONING), + ) + } + } + + /** + * A renderer reporting ERROR_OCCURRED is the unambiguous signal, and it + * should not have to also say STOPPED before we act. + */ + @Test + fun `a transport reporting an error counts as a stall`() { + val w = RemoteStallWatchdog() + var last: RemoteStallWatchdog.Decision = RemoteStallWatchdog.Decision.None + repeat(3) { last = w.poll(state = TransportState.PLAYING, statusOk = false) } + assertIs(last) + } + + @Test + fun `retries are spaced out rather than fired every poll`() { + val w = RemoteStallWatchdog() + assertIs(w.stopFor(3, nowMs = 0L)) + // Immediately after, still stopped: too soon to try again. + assertIs(w.stopFor(1, nowMs = 1_000L)) + assertIs(w.stopFor(1, nowMs = 4_999L)) + // Past the spacing, the next attempt goes out. + val second = w.stopFor(1, nowMs = 5_000L) + assertIs(second) + assertEquals(2, second.attempt) + } + + /** + * The failure this guards against is an unplayable file turning into an + * endless retry loop against the renderer. + */ + @Test + fun `attempts are capped and then it gives up exactly once`() { + val w = RemoteStallWatchdog() + assertIs(w.stopFor(3, nowMs = 0L)) + assertIs(w.stopFor(1, nowMs = 5_000L)) + assertIs(w.stopFor(1, nowMs = 10_000L)) + assertIs(w.stopFor(1, nowMs = 15_000L)) + // Reported once; after that it stays quiet instead of spamming. + repeat(20) { + assertIs(w.stopFor(1, nowMs = 20_000L + it * 5_000L)) + } + } + + @Test + fun `moving to another track restores the attempt budget`() { + val w = RemoteStallWatchdog() + assertIs(w.stopFor(3, nowMs = 0L)) + assertIs(w.stopFor(1, nowMs = 5_000L)) + assertIs(w.stopFor(1, nowMs = 10_000L)) + assertIs(w.stopFor(1, nowMs = 15_000L)) + + // A different track is a different problem. + w.poll(trackUri = other, state = TransportState.PLAYING, nowMs = 16_000L) + w.poll(trackUri = other, state = TransportState.STOPPED, nowMs = 20_000L) + w.poll(trackUri = other, state = TransportState.STOPPED, nowMs = 20_000L) + // Held in a val: a var mutated inside a lambda can't be smart-cast. + val onNewTrack = w.poll(trackUri = other, state = TransportState.STOPPED, nowMs = 20_000L) + assertIs(onNewTrack) + assertEquals(1, onNewTrack.attempt) + } + + /** + * A track that stalls, recovers and stalls again later gets the full + * budget the second time — otherwise one bad patch early in a long track + * would leave it defenceless for the rest. + */ + @Test + fun `recovering to playing restores the attempt budget`() { + val w = RemoteStallWatchdog() + assertIs(w.stopFor(3, nowMs = 0L)) + w.poll(state = TransportState.PLAYING, positionMs = 60_000L, nowMs = 6_000L) + + val again = w.stopFor(3, nowMs = 30_000L) + assertIs(again) + assertEquals(1, again.attempt) + assertEquals(60_000L, again.resumeAtMs) + } + + @Test + fun `reset forgets everything`() { + val w = RemoteStallWatchdog() + assertIs(w.stopFor(3, nowMs = 0L)) + w.reset() + val afterReset = w.stopFor(3, nowMs = 1_000L) + assertIs(afterReset) + assertEquals(1, afterReset.attempt) + assertTrue(afterReset.resumeAtMs == 0L) + } +}