UPnP: verify the Sonos queue landed, stop the phone double-downloading, and instrument the stutter #127

Merged
bvandeusen merged 4 commits from dev into main 2026-08-18 10:50:10 -04:00
7 changed files with 381 additions and 7 deletions
Showing only changes of commit 72c0e96f92 - Show all commits
@@ -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<TransportObservation>) {
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.
@@ -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<TransportObservation>()
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<TransportObservation>? {
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
}
}
@@ -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<TransportState, Boolean>? = 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].
*
@@ -77,6 +77,13 @@ class PlayerController @Inject constructor(
* during UPnP playback shows "Disconnected from <name>" to the user.
*/
val dropEvents: SharedFlow<String> = 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<TransportObservation> = playerFactory.transportEvents
private val sessionToken =
SessionToken(context, ComponentName(context, MinstrelPlayerService::class.java))
@@ -95,6 +95,18 @@ class PlayerFactory @Inject constructor(
)
val queueRepairEvents: SharedFlow<Unit> = 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<TransportObservation>(
replay = 0,
extraBufferCapacity = TRANSPORT_EVENT_BUFFER,
onBufferOverflow = BufferOverflow.DROP_OLDEST,
)
val transportEvents: SharedFlow<TransportObservation> = 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)
}
@@ -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,
)
@@ -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)
}
}