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

2026-08-18T10:50:04-04:00

bvandeusen commented

2026-08-18 10:50:04 -04:00

Four commits, all Android/UPnP. CI green on head 01039539 (run 3916).

This batch exists because the operator rejected the framing of the last one:

that sounds like you're assuming the issue is in the network and not something that can be solved in the app [...] please assume that the app is where all issues live and the only thing we can or should change.

Re-read app-only, the same diagnostics pointed somewhere better, and a second symptom turned out to be a different bug entirely.

The queue was written blind — #2728

loadQueueOnSonos sends the queue to the renderer and never reads it back — GetMediaInfo / NrTracks appeared nowhere in the app. The append loop gives up after 3 consecutive AddURIToQueue failures, and Sonos rate-limits burst adds; the in-tree comment at the old OutputPickerController.kt:776 already recorded 33 consecutive failures at offset ~39 from logcat 2026-06-04.

So the renderer ends up holding fewer tracks than the app believes, plays what it actually has, and stops — correctly. That is the session that ends in silence, and it is not a stream dying.

AVTransportClient.getMediaInfo(). NrTracks=0 reads as unknown, never empty — a renderer that doesn't implement it must not have its queue "repaired" out from under it.
verifyQueueLength after every load, including when there is no tail to append (the initial batch can be dropped the same way), appending what's missing, bounded at 2 passes.
RemoteStallWatchdog.QueueState classifies a stop instead of assuming: dead stream resumes, truncated queue repairs at the next track (the current one just finished), completed queue does nothing.

This also fixes a bug shipped in PR #126 this week. The watchdog treated any confirmed STOPPED-with-play-intent as a stall — which is exactly what the normal end of a queue looks like. Every cast session would have ended with three resume attempts and a stalled error, snackbar plus admin-inbox row, for playback that finished perfectly. CI never caught it because no test described the end of a queue; one does now.

SonosQueueLoader was extracted when detekt flagged LargeClass — load / extend / verify / append plus the incremental diff, out of the route-selection controller. 985 → 711 lines, no behaviour change.

The stutter is a different bug — #2734

The operator's first precise description: the Sonos play-pause-play-pausing roughly twice a second, usually as a track starts, cleared by a manual pause or skip.

Nothing in the diagnostics could see it. player_state carries source/loading/error but not whether we're playing; track_change needs the queue index to move; the heartbeat samples once per 45s. A few seconds of oscillation at one track fell through all three — which is why this has been reported repeatedly and measured never.

Raw GetTransportInfo readings now publish on change (steady playback emits nothing; a normal advance emits 2–3).
TransportFlapDetector — pure, 8 tests, same shape as the watchdog — turns a burst into one transport_flap event carrying the state sequence, per-reading Sonos position/track, and the local index/track/position beside them. Local and Sonos disagreeing means a cursor fight; agreeing while position resets means the renderer is rebuffering. Opposite fixes, and one episode separates them.
Documented limit: it samples at the 1 Hz poll cadence, so a faster oscillation lands aliased. It answers "is the renderer leaving PLAYING", not the period.

And one real defect found while looking: during a cast the wrapped ExoPlayer was paused, not stopped. pause() is only playWhenReady=false — LoadControl keeps loading, so the phone went on downloading the track the renderer was streaming, over the same WiFi, re-arming at every track change via syncLocalCursorToRemote's seekTo. FLAC at ~1000 kbps, starting exactly when a new track does. Now stop(), with prepare() on route teardown; Media3 keeps media items, index and position, and getPlaybackState() already reported STATE_READY while remote.

What CI cannot sign off

Whether the truncated-queue reading of "stopped at track 10" is right. It is inference from the code plus the 06-04 logcat, never confirmed against hardware. The new UPnP verify: log lines report renderer-held vs local count on every cast and will settle it.
Whether the double-download was causing the stutter. It is a candidate, not a diagnosis — the previous theory about these symptoms was wrong, which is why the instrument ships alongside the fix rather than after it.
All of it is device-verify: there is no Sonos in CI.

Four commits, all Android/UPnP. CI green on head `01039539` (run 3916). This batch exists because the operator rejected the framing of the last one: > that sounds like you're assuming the issue is in the network and not something that can be solved in the app [...] please assume that the app is where all issues live and the only thing we can or should change. Re-read app-only, the same diagnostics pointed somewhere better, and a second symptom turned out to be a different bug entirely. ## The queue was written blind — #2728 `loadQueueOnSonos` sends the queue to the renderer and never reads it back — `GetMediaInfo` / `NrTracks` appeared nowhere in the app. The append loop gives up after 3 consecutive `AddURIToQueue` failures, and Sonos rate-limits burst adds; the in-tree comment at the old `OutputPickerController.kt:776` already recorded 33 consecutive failures at offset ~39 from logcat 2026-06-04. So the renderer ends up holding fewer tracks than the app believes, plays what it actually has, and stops — correctly. That is the session that ends in silence, and it is not a stream dying. - `AVTransportClient.getMediaInfo()`. `NrTracks=0` reads as *unknown*, never *empty* — a renderer that doesn't implement it must not have its queue "repaired" out from under it. - `verifyQueueLength` after every load, including when there is no tail to append (the initial batch can be dropped the same way), appending what's missing, bounded at 2 passes. - `RemoteStallWatchdog.QueueState` classifies a stop instead of assuming: dead stream resumes, truncated queue repairs at the **next** track (the current one just finished), completed queue does nothing. **This also fixes a bug shipped in PR #126 this week.** The watchdog treated any confirmed STOPPED-with-play-intent as a stall — which is exactly what the normal end of a queue looks like. Every cast session would have ended with three resume attempts and a `stalled` error, snackbar plus admin-inbox row, for playback that finished perfectly. CI never caught it because no test described the end of a queue; one does now. `SonosQueueLoader` was extracted when detekt flagged `LargeClass` — load / extend / verify / append plus the incremental diff, out of the route-selection controller. 985 → 711 lines, no behaviour change. ## The stutter is a different bug — #2734 The operator's first precise description: the Sonos play-pause-play-pausing roughly twice a second, usually as a track starts, cleared by a manual pause or skip. **Nothing in the diagnostics could see it.** `player_state` carries source/loading/error but not whether we're playing; `track_change` needs the queue index to move; the heartbeat samples once per 45s. A few seconds of oscillation at one track fell through all three — which is why this has been reported repeatedly and measured never. - Raw `GetTransportInfo` readings now publish on *change* (steady playback emits nothing; a normal advance emits 2–3). - `TransportFlapDetector` — pure, 8 tests, same shape as the watchdog — turns a burst into one `transport_flap` event carrying the state sequence, per-reading Sonos position/track, and the local index/track/position beside them. Local and Sonos disagreeing means a cursor fight; agreeing while position resets means the renderer is rebuffering. Opposite fixes, and one episode separates them. - Documented limit: it samples at the 1 Hz poll cadence, so a faster oscillation lands aliased. It answers "is the renderer leaving PLAYING", not the period. And one real defect found while looking: during a cast the wrapped ExoPlayer was **paused, not stopped**. `pause()` is only `playWhenReady=false` — LoadControl keeps loading, so the phone went on downloading the track the renderer was streaming, over the same WiFi, re-arming at every track change via `syncLocalCursorToRemote`'s `seekTo`. FLAC at ~1000 kbps, starting exactly when a new track does. Now `stop()`, with `prepare()` on route teardown; Media3 keeps media items, index and position, and `getPlaybackState()` already reported `STATE_READY` while remote. ## What CI cannot sign off - Whether the truncated-queue reading of "stopped at track 10" is right. It is inference from the code plus the 06-04 logcat, never confirmed against hardware. The new `UPnP verify:` log lines report renderer-held vs local count on every cast and will settle it. - Whether the double-download was causing the stutter. It is a candidate, not a diagnosis — the previous theory about these symptoms was wrong, which is why the instrument ships alongside the fix rather than after it. - All of it is device-verify: there is no Sonos in CI.

bvandeusen added 4 commits 2026-08-18 10:50:04 -04:00

fix(player): verify the Sonos queue actually landed — #2728

android / Build + lint + test (push) Failing after 1m18s

Details

8e21bce103

The renderer's queue was written and never read back. loadQueueOnSonos
background-appends the tail one AddURIToQueue at a time and gives up
after 3 consecutive failures; Sonos rate-limits burst adds, so that
happens. The renderer was then left holding fewer tracks than we
believed, played what it actually had, and stopped — which looked
exactly like playback dying for no reason.

GetMediaInfo's NrTracks is the cheap authoritative answer and was not
being asked for anywhere in the app. Now:

- verifyQueueLength after every load (including when there is no tail
  to append — the initial batch can be dropped the same way), appending
  what the renderer is missing, bounded at 2 passes.
- RemoteStallWatchdog gains QueueState, so a stop is classified rather
  than assumed: a stream that died resumes, a truncated queue gets
  repaired at the next track, and a queue that simply ended does
  nothing at all.

That last case was a bug shipped in #2700: the normal end of a queue is
a confirmed STOPPED with play intent, so every cast session would have
ended with three resume attempts and a `stalled` error for playback
that finished perfectly. No test described the end of a queue, so CI
had nothing to catch it with.

Queue reads are gated on the transport being stopped and cached for 5s,
so this never becomes a third SOAP call per second.

refactor(player): split Sonos queue loading out of the picker — #2728

android / Build + lint + test (push) Successful in 3m48s

Details

e87516bbe4

detekt flagged OutputPickerController as LargeClass once the verify
path landed. Extracting rather than suppressing: how the renderer's
queue is shaped is a different concern from which route is selected,
and it had grown big enough to hide a bug — every write in here is a
SOAP call that can fail on its own, and nothing ever read the result
back.

SonosQueueLoader now owns load / extend / verify / append and the
incremental diff. The picker keeps route selection and asks it for
queue work. No behaviour change.

fix(player): stop the local player during a cast; capture transport flap

android / Build + lint + test (push) Failing after 1m11s

Details

72c0e96f92

Two changes for the Sonos stutter the operator describes as rapid
play-pause-play at the start of a track.

The measurable one: nothing in the diagnostics could see it.
player_state records source/loading/error but not whether we are
playing, track_change needs the queue index to move, and the heartbeat
samples once every 45s. A few seconds of oscillation that changes no
index fell through all three, which is why the symptom has been
described repeatedly and measured never. The poll loop now publishes
raw GetTransportInfo readings on change, and TransportFlapDetector
turns a burst of them into one summary event carrying the sequence
alongside local-vs-Sonos track and position -- enough to tell a cursor
disagreement from the renderer rebuffering. It samples at the 1Hz poll
cadence, so a faster oscillation lands aliased; that still answers
whether the renderer is leaving PLAYING, which is the open question.

The suspect one: during a cast the wrapped ExoPlayer was paused, not
stopped. pause() is only playWhenReady=false -- LoadControl keeps
loading, so the phone went on downloading the track the renderer was
streaming, over the same WiFi, re-arming at every track change via
syncLocalCursorToRemote's seekTo. At FLAC bitrates that is a second
full-rate download competing with the speaker, beginning exactly when
a new track does. stop() ends it; Media3 keeps media items, index and
position, and getPlaybackState() already reports STATE_READY while
remote, so cursor sync and handoff are unaffected. The route teardown
re-prepares for local playback.

Whether that download is the cause is unproven -- hence the
instrument landing alongside it rather than after it.

refactor(diagnostics): split the flap window and episode rule apart

android / Build + lint + test (push) Successful in 4m8s

Details

0103953953

detekt ReturnCount. Extracting the pruning and the is-this-an-episode
predicate reads better than suppressing it, and the cooldown rule now
has a name and a docstring of its own.

bvandeusen merged commit 4f077736b6 into main

2026-08-18 10:50:10 -04:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: bvandeusen/minstrel#127