diff --git a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt index 142f5a2b..4ce6f4f0 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/DiagnosticsReporter.kt @@ -18,6 +18,7 @@ import com.fabledsword.minstrel.connectivity.NetworkStatusController import com.fabledsword.minstrel.di.ApplicationScope import com.fabledsword.minstrel.player.PlayerController import com.fabledsword.minstrel.player.RemotePlayerState +import com.fabledsword.minstrel.player.TransportObservation import com.fabledsword.minstrel.player.output.OutputPickerController import com.fabledsword.minstrel.player.output.OutputRoute import dagger.hilt.android.qualifiers.ApplicationContext @@ -103,6 +104,7 @@ class DiagnosticsReporter @Inject constructor( launch { collectUpnpDrops() } launch { collectPlayerState() } launch { collectTrackChanges() } + launch { collectTransportFlap() } launch { collectRoutes() } launch { heartbeatLoop() } } @@ -191,6 +193,67 @@ class DiagnosticsReporter @Inject constructor( } } + /** + * Catch the renderer rapidly leaving and re-entering PLAYING. + * + * The operator reports the Sonos "play pause play pause, like someone + * pressing it every half second", usually as a track starts, cleared by a + * manual pause or skip. Nothing here could see that: `player_state` + * carries source/loading/error but not playing, `track_change` needs the + * index to move, and the heartbeat samples once per 45s. The symptom fell + * through every existing collector, which is why it has only ever been + * described and never measured. + * + * Records every raw transport change (cheap — steady playback produces + * a couple per track) and, when they come in a burst, one summary event + * carrying the whole sequence. The summary is the useful artefact: it + * pairs the renderer's states with local-vs-Sonos track and position, so + * an episode says whether the app and the renderer disagreed about which + * track was playing, or agreed while the renderer rebuffered. + * + * See [TransportObservation] on the 1 Hz sampling limit. + */ + private suspend fun collectTransportFlap() { + val detector = TransportFlapDetector() + playerController.transportEvents.collect { obs -> + record("upnp_sync", buildJsonObject { + put("event", "transport") + put("state", obs.state) + put("status_ok", obs.statusOk) + put("sonos_track", obs.trackNumber) + put("sonos_pos_ms", obs.positionMs) + put("play_intent", obs.playIntent) + }) + detector.onChange(obs)?.let { recordFlapSummary(it) } + } + } + + private suspend fun recordFlapSummary(recent: List) { + val ui = playerController.uiState.value + val casting = outputPicker.routesState.value.current.protocol != + OutputRoute.Protocol.SYSTEM + val spanMs = recent.last().atElapsedMs - recent.first().atElapsedMs + record("upnp_sync", buildJsonObject { + put("event", "transport_flap") + put("changes", recent.size) + put("window_ms", spanMs) + // The sequence itself, e.g. "PLAYING>TRANSITIONING>STOPPED>PLAYING". + // Whether STOPPED appears at all is the first question to ask of a + // captured episode. + put("sequence", recent.joinToString(">") { it.state }) + put("sonos_positions_ms", recent.joinToString(",") { it.positionMs.toString() }) + put("sonos_tracks", recent.joinToString(",") { it.trackNumber.toString() }) + put("local_index", ui.queueIndex) + put("local_track_id", ui.currentTrack?.id ?: "") + put("local_pos_ms", ui.positionMs) + putSonos(this, casting) + put("upnp_loading", ui.isUpnpLoading) + put("server_health", networkStatus.state.value.name) + put("route", outputPicker.routesState.value.current.name) + addPowerFields(this) + }) + } + private suspend fun collectRoutes() { // 'playback' — route changes happen for all outputs. This only ever // logs the ACTIVE route (routesState.current), so no "connected" flag. diff --git a/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt new file mode 100644 index 00000000..2297914a --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetector.kt @@ -0,0 +1,65 @@ +package com.fabledsword.minstrel.diagnostics + +import com.fabledsword.minstrel.player.TransportObservation + +/** + * Decides when a run of renderer transport changes is a *flap* — the renderer + * repeatedly failing to settle — rather than an ordinary track transition. + * + * The operator reports the Sonos "play pause play pause, like someone pressing + * it every half second", usually as a track starts. No diagnostic event could + * see it, so it has been described several times and measured never. This is + * the rule that decides when an episode is worth writing down. + * + * Pure decision state, like [com.fabledsword.minstrel.player.RemoteStallWatchdog]: + * the caller owns the flow and the recording, this only answers "is this an + * episode, and which readings make it up". Keeps the windowing and the + * one-episode-one-summary rule testable without a renderer or a clock. + */ +class TransportFlapDetector( + private val windowMs: Long = FLAP_WINDOW_MS, + private val minChanges: Int = FLAP_MIN_CHANGES, + private val summaryCooldownMs: Long = FLAP_SUMMARY_COOLDOWN_MS, +) { + private val recent = ArrayDeque() + private var lastSummaryAtMs: Long? = null + + /** + * Feed one transport change. Returns the readings making up an episode + * worth recording, or null when there is nothing to say. + * + * The returned list is a copy: the caller may hold it while more readings + * arrive. + */ + fun onChange(observation: TransportObservation): List? { + recent.addLast(observation) + while (recent.isNotEmpty() && + observation.atElapsedMs - recent.first().atElapsedMs > windowMs + ) { + recent.removeFirst() + } + if (recent.size < minChanges) return null + // One episode, one summary. A sustained fault would otherwise emit a + // summary per reading and bury the per-change events underneath them. + val since = lastSummaryAtMs + if (since != null && observation.atElapsedMs - since < summaryCooldownMs) return null + lastSummaryAtMs = observation.atElapsedMs + return recent.toList() + } + + /** Forget everything — call when the route changes or casting ends. */ + fun reset() { + recent.clear() + lastSummaryAtMs = null + } + + companion object { + // Readings arrive at the 1 Hz poll cadence, and a normal track + // transition is 2-3 changes (PLAYING -> TRANSITIONING -> PLAYING). + // Four inside six seconds is not a track change, and it is not a + // person at the Sonos app either; it is the renderer not settling. + const val FLAP_WINDOW_MS = 6_000L + const val FLAP_MIN_CHANGES = 4 + const val FLAP_SUMMARY_COOLDOWN_MS = 60_000L + } +} diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt index fcb55d3a..1556bb42 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/MinstrelForwardingPlayer.kt @@ -14,6 +14,7 @@ import com.fabledsword.minstrel.connectivity.NetworkStatusController import com.fabledsword.minstrel.connectivity.ServerHealth import com.fabledsword.minstrel.player.output.ActiveUpnp import com.fabledsword.minstrel.player.output.ActiveUpnpHolder +import com.fabledsword.minstrel.player.output.upnp.PositionInfo import com.fabledsword.minstrel.player.output.upnp.SoapFaultException import com.fabledsword.minstrel.player.output.upnp.TransportInfo import com.fabledsword.minstrel.player.output.upnp.TransportState @@ -87,6 +88,11 @@ class MinstrelForwardingPlayer( val onStalled: (trackId: String) -> Unit = {}, /** The renderer's queue is short of ours and needs rebuilding. */ val onQueueTruncated: () -> Unit = {}, + /** + * A raw poll reading, emitted only when it differs from the previous + * one. Diagnostics-only; see [TransportObservation]. + */ + val onTransport: (TransportObservation) -> Unit = {}, ) private val scope = CoroutineScope(SupervisorJob() + Dispatchers.IO) @@ -117,6 +123,10 @@ class MinstrelForwardingPlayer( @Volatile private var cachedNrTracks: Int = 0 @Volatile private var lastMediaInfoAtMs: Long = 0L + // Previous raw transport reading, so [TransportObservation]s are emitted + // on change rather than once a second forever. Null until the first poll. + @Volatile private var lastObservedTransport: Pair? = null + // Wake channel for the poll loop. requestImmediatePoll() trySend's a Unit; // pollLoop's select{} races the delay against this channel so the next // pollOnce can fire immediately instead of waiting up to POLL_INTERVAL_MS. @@ -508,17 +518,35 @@ class MinstrelForwardingPlayer( // without this the radio power-saves on a locked screen and the // poll below starves -- see [CastNetworkLock]. castNetworkLock.acquire() - // Pause the wrapped ExoPlayer so we are not playing local audio - // simultaneously with the remote renderer. handler.post targets the - // application looper, so this runs on the same thread that processes - // our override calls -- no race with the pause() override branching - // to SOAP (holder.active is already non-null by the time this post - // fires, but delegate.pause() bypasses the override entirely). - handler.post { delegate.pause() } + // STOP the wrapped ExoPlayer -- not pause. pause() is only + // playWhenReady=false: ExoPlayer's LoadControl keeps loading, so a + // paused-but-prepared player goes on downloading the current track + // (~50s of buffer). During a cast that means the phone pulls the + // same file the renderer is streaming, over the same WiFi, and + // re-arms on every track change via syncLocalCursorToRemote's + // seekTo. At FLAC bitrates that is a second full-rate download + // competing with the speaker for air, starting exactly when a new + // track does. stop() ends the loading; Media3 keeps the media + // items, the current index and the position, so cursor sync and + // the handoff back are unaffected, and getPlaybackState() already + // reports STATE_READY while remote so no external reader sees IDLE. + // + // handler.post targets the application looper, so this runs on the + // same thread that processes our override calls -- no race with the + // pause() override branching to SOAP (holder.active is already + // non-null by the time this post fires, but delegate.stop() + // bypasses the override entirely). + handler.post { delegate.stop() } pollJob = scope.launch { pollLoop(active) } } else { castNetworkLock.release() remoteState.reset() + lastObservedTransport = null + // The delegate was stopped for the cast, so it is IDLE and would + // ignore a play(). Re-prepare it for local playback. Safe when the + // queue is empty, and it does not start playback on its own -- + // playWhenReady is still false until something calls play(). + handler.post { delegate.prepare() } // The next cast starts with a clean attempt budget; a stall on the // route we just left says nothing about the next one. stallWatchdog.reset() @@ -614,6 +642,7 @@ class MinstrelForwardingPlayer( } TransportState.TRANSITIONING, TransportState.UNKNOWN -> Unit } + observeTransport(transport, info) checkForStall(active, info.trackUri, transport) notifyRemoteStateChanged() } @@ -685,6 +714,31 @@ class MinstrelForwardingPlayer( } } + /** + * Publish this poll's raw transport reading if it differs from the last. + * + * Change-gated on purpose: steady playback is one reading repeated once a + * second, which is worth nothing and would fill the ring buffer. What is + * worth capturing is the renderer LEAVING a state — which during normal + * playback happens a couple of times per track, and during the fault the + * operator describes should happen repeatedly within a few seconds. + */ + private fun observeTransport(transport: TransportInfo, info: PositionInfo) { + val key = transport.state to transport.statusOk + if (key == lastObservedTransport) return + lastObservedTransport = key + events.onTransport( + TransportObservation( + state = transport.state.name, + statusOk = transport.statusOk, + trackNumber = info.track, + positionMs = info.relTimeMs, + playIntent = remoteState.lastPlayIntent, + atElapsedMs = SystemClock.elapsedRealtime(), + ), + ) + } + /** * How the renderer's queue compares to ours, for [RemoteStallWatchdog]. * diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt index 631b0ad5..44c1b01c 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerController.kt @@ -77,6 +77,13 @@ class PlayerController @Inject constructor( * during UPnP playback shows "Disconnected from " to the user. */ val dropEvents: SharedFlow = playerFactory.dropEvents + + /** + * Raw UPnP transport readings from [PlayerFactory.transportEvents], for + * the diagnostics reporter. Read-only tap — nothing in the playback path + * consumes it. + */ + val transportEvents: SharedFlow = playerFactory.transportEvents private val sessionToken = SessionToken(context, ComponentName(context, MinstrelPlayerService::class.java)) diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt index 05bda717..741c024c 100644 --- a/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/PlayerFactory.kt @@ -95,6 +95,18 @@ class PlayerFactory @Inject constructor( ) val queueRepairEvents: SharedFlow = queueRepairInternal.asSharedFlow() + // Raw renderer transport readings, change-gated. Unlike the flows above + // this one carries a SEQUENCE — the diagnostics flap detector needs + // several readings in a row to tell oscillation from a normal track + // transition — so it buffers more than one and drops oldest under + // pressure rather than collapsing to the latest. + private val transportInternal = MutableSharedFlow( + replay = 0, + extraBufferCapacity = TRANSPORT_EVENT_BUFFER, + onBufferOverflow = BufferOverflow.DROP_OLDEST, + ) + val transportEvents: SharedFlow = transportInternal.asSharedFlow() + fun build(): Player { val exo = buildExoPlayer() return MinstrelForwardingPlayer( @@ -107,6 +119,7 @@ class PlayerFactory @Inject constructor( onDrop = { name -> emitDrop(name) }, onStalled = { trackId -> stallEventsInternal.tryEmit(trackId) }, onQueueTruncated = { queueRepairInternal.tryEmit(Unit) }, + onTransport = { transportInternal.tryEmit(it) }, ), ) } @@ -160,6 +173,12 @@ class PlayerFactory @Inject constructor( .build(), ) + private companion object { + // Enough readings to hold a whole flap episode plus the normal + // transitions around it; the detector's window is only a few seconds. + const val TRANSPORT_EVENT_BUFFER = 32 + } + private fun emitDrop(routeName: String) { dropEventsInternal.tryEmit(routeName) } diff --git a/android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt b/android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt new file mode 100644 index 00000000..f816efac --- /dev/null +++ b/android/app/src/main/java/com/fabledsword/minstrel/player/TransportObservation.kt @@ -0,0 +1,38 @@ +package com.fabledsword.minstrel.player + +/** + * One reading of what a UPnP renderer says it is doing, taken by the poll + * loop and emitted only when it differs from the previous reading. + * + * Exists for diagnostics. The operator reports the Sonos rapidly + * play-pause-play-pausing at the start of a track, and nothing in the + * diagnostics could see it: `player_state` records source / loading / error + * but not whether we are playing, `track_change` needs the queue index to + * move, and the heartbeat samples once every 45 seconds. A symptom that + * lasts a few seconds and changes no index fell straight through all three. + * + * This is the closest observation point we have to the renderer's own truth + * — the raw GetTransportInfo reading, before the two-poll confirmation and + * the UI's smoothing have had a chance to hide the wobble. + * + * **It samples at the poll cadence (1 Hz).** If the real oscillation is + * faster than that, what lands here is an aliased jagged sequence rather + * than the true waveform. That still answers the question that matters — + * whether the renderer is steadily PLAYING or repeatedly leaving that state + * — but it cannot measure the true period. If a captured episode comes back + * looking clean, the next instrument is burst sampling, not this one. + */ +data class TransportObservation( + /** [com.fabledsword.minstrel.player.output.upnp.TransportState] name. */ + val state: String, + /** CurrentTransportStatus: false means the renderer reports an error. */ + val statusOk: Boolean, + /** The renderer's 1-based queue position at this reading. */ + val trackNumber: Int, + /** The renderer's reported position within the track. */ + val positionMs: Long, + /** Whether the operator's last intent was to be playing. */ + val playIntent: Boolean, + /** Monotonic stamp, so a consumer can measure gaps between readings. */ + val atElapsedMs: Long, +) diff --git a/android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt b/android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt new file mode 100644 index 00000000..490e4615 --- /dev/null +++ b/android/app/src/test/java/com/fabledsword/minstrel/diagnostics/TransportFlapDetectorTest.kt @@ -0,0 +1,128 @@ +package com.fabledsword.minstrel.diagnostics + +import com.fabledsword.minstrel.player.TransportObservation +import org.junit.jupiter.api.Test +import kotlin.test.assertEquals +import kotlin.test.assertNotNull +import kotlin.test.assertNull + +/** + * The rule deciding when renderer transport changes are worth recording as an + * episode. Worth pinning because both failure directions are costly: too eager + * and every track transition writes a summary that buries the real one, too + * shy and the operator's stutter goes unmeasured for another month. + */ +class TransportFlapDetectorTest { + + private fun obs(state: String, atMs: Long, track: Int = 1, posMs: Long = 0L) = + TransportObservation( + state = state, + statusOk = true, + trackNumber = track, + positionMs = posMs, + playIntent = true, + atElapsedMs = atMs, + ) + + /** + * PLAYING -> TRANSITIONING -> PLAYING is what a queue advance looks like. + * It happens on every single track and must never be recorded as a fault. + */ + @Test + fun `an ordinary track transition is not an episode`() { + val d = TransportFlapDetector() + assertNull(d.onChange(obs("PLAYING", 0))) + assertNull(d.onChange(obs("TRANSITIONING", 1_000))) + assertNull(d.onChange(obs("PLAYING", 2_000))) + } + + @Test + fun `four changes inside the window is an episode`() { + val d = TransportFlapDetector() + d.onChange(obs("PLAYING", 0)) + d.onChange(obs("STOPPED", 500)) + d.onChange(obs("PLAYING", 1_000)) + // assertNotNull returns the value, so the asserts below need no cast. + val episode = assertNotNull(d.onChange(obs("STOPPED", 1_500))) + assertEquals(4, episode.size) + assertEquals( + listOf("PLAYING", "STOPPED", "PLAYING", "STOPPED"), + episode.map { it.state }, + ) + } + + /** + * Changes spread thinly are normal listening — a few track advances over + * a couple of minutes must not accumulate into a false episode. + */ + @Test + fun `changes spread beyond the window never accumulate`() { + val d = TransportFlapDetector() + repeat(20) { i -> + assertNull(d.onChange(obs("PLAYING", i * 10_000L))) + } + } + + /** The window slides: old readings age out rather than counting forever. */ + @Test + fun `readings older than the window are dropped`() { + val d = TransportFlapDetector() + d.onChange(obs("PLAYING", 0)) + d.onChange(obs("STOPPED", 1_000)) + // Long gap — the two above are now stale. + assertNull(d.onChange(obs("PLAYING", 30_000))) + assertNull(d.onChange(obs("STOPPED", 30_500))) + // Only three fresh readings so far. + assertNull(d.onChange(obs("PLAYING", 31_000))) + assertNotNull(d.onChange(obs("STOPPED", 31_500))) + } + + /** + * A fault that persists produces a change every poll. Without the cooldown + * every one of them would write a summary, which is exactly the noise that + * makes a diagnostics dump unreadable. + */ + @Test + fun `a sustained fault reports one episode, not one per reading`() { + val d = TransportFlapDetector() + var episodes = 0 + repeat(40) { i -> + if (d.onChange(obs(if (i % 2 == 0) "PLAYING" else "STOPPED", i * 500L)) != null) { + episodes++ + } + } + assertEquals(1, episodes) + } + + /** Past the cooldown, a fresh episode is worth recording again. */ + @Test + fun `a later episode reports again once the cooldown has passed`() { + val d = TransportFlapDetector() + repeat(4) { d.onChange(obs("PLAYING", it * 500L)) } + val second = (0 until 4).map { d.onChange(obs("STOPPED", 90_000 + it * 500L)) } + assertEquals(1, second.count { it != null }) + } + + @Test + fun `reset forgets the window and the cooldown`() { + val d = TransportFlapDetector() + repeat(4) { d.onChange(obs("PLAYING", it * 500L)) } + d.reset() + repeat(3) { d.onChange(obs("PLAYING", 3_000 + it * 500L)) } + // A 4th change after reset is a new episode, cooldown notwithstanding. + assertNotNull(d.onChange(obs("STOPPED", 5_000))) + } + + /** The episode is a snapshot — later readings must not mutate it. */ + @Test + fun `a returned episode is not mutated by later readings`() { + val d = TransportFlapDetector() + d.onChange(obs("PLAYING", 0)) + d.onChange(obs("STOPPED", 500)) + d.onChange(obs("PLAYING", 1_000)) + val episode = assertNotNull(d.onChange(obs("STOPPED", 1_500))) + val sizeAtCapture = episode.size + repeat(5) { d.onChange(obs("PLAYING", 2_000 + it * 500L)) } + assertEquals(sizeAtCapture, episode.size) + } +}