Mid-session format change leaves the stream desynced until a manual pause/play

[chrisuthe]

Summary

On a live format renegotiation (FLAC 48 kHz/16-bit -> 192 kHz/24-bit) mid-session, the
output sink reconfigures to the new format but no codec header is ever processed for
it. The player then loses sync and fails to place audio chunks for the rest of that
stream. It does not self-recover: audio stayed audibly wrong until a manual pause/play,
which tore the stream down and started a new one that did process a codec header and
then played correctly.

Environment

sendspin-cli	0.1.4, commit 52d0f2c (release artifact linux-arm64, CI run 33119241602)
sendspin-cpp	v0.7.2
Host	Raspberry Pi 5, Debian 13 (trixie), aarch64, kernel 6.12.47
Output	-o pipewire (native backend), libpipewire 1.4.2 + wireplumber
Sink	Built-in HDMI, s32le 2ch 48000Hz (so the graph resamples 4:1 from 192 kHz)
Server	Music Assistant

Timeline

I player: Stream started
I audio: pipewire: 'pipewire' open at 48000 Hz, 2 ch, 16-bit (4 bytes/frame, 19201-byte ring)
I sendspin.sync_task: Processed new codec header: flac, 48000 Hz, 2 ch, 16-bit
I metadata: Now playing: Ed Sheeran - Perfect
I player: Static delay set to 0 ms by the server
I player: Stream started
I audio: pipewire: 'pipewire' open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
W sendspin.sync_task: Lost sync (43890us off), reporting error
I sendspin.sync_task: Regained sync, reporting synchronized
W sendspin.sync_task: Lost sync (64710us off), reporting error
W sendspin.player: Failed to send audio chunk
   ... x76 ...

Then the manual pause/play:

I player: Stream ended
I player: Stream started
I audio: pipewire: 'pipewire' open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
I sendspin.sync_task: Processed new codec header: flac, 192000 Hz, 2 ch, 24-bit

No further warnings after that: the counter held at 76 across a 10 s window, through two
more 192 kHz stream opens and a track change.

The suspicious part

Three sink opens in one run, and only the broken one is missing its codec header:

Stream open	Sink opened at	Processed new codec header
1st	48 kHz / 16-bit	yes
2nd (broken)	192 kHz / 24-bit	absent
3rd, after pause/play	192 kHz / 24-bit	yes

So the sink was reconfigured to the new format while the decode path had never been told
about it. That is consistent with the symptom -- the two Lost sync figures (43.9 ms and
64.7 ms) are roughly what a 4x sample-rate mismatch would produce against a stream clock.

What it does not appear to be

• Not sink starvation, and not ring mis-sizing. The ring was correct for both formats:
  19201 bytes / 4 bytes-per-frame = 4800 frames = 100 ms at 48 kHz, and
  115201 / 6 = 19200 frames = also 100 ms at 192 kHz. The quantum-starvation warning
  added in Add native PulseAudio and PipeWire output backends #27 never fired.
• Not an output-backend write failure. Every warning is tagged sendspin.player or
  sendspin.sync_task. Nothing logged under the audio: tag at all, so the sink never
  reported a short write, a dead stream, or a recovery attempt.
• Not volume or mute. The stream sat at 100% / 0.00 dB in the graph throughout, and
  the player reported player volume: 100 (default; no server has set it).

That points at the stream-restart / codec-header path rather than the output backend. It
may well live in sendspin-cpp rather than in this repo -- filing here because this is
where it was observed and where -o pipewire lives, and the triage can move it.

Open questions

• Does it reproduce on -o pulse and -o alsa? If so it is backend-independent, which
  would confirm the diagnosis above.
• Does it need the 4x rate jump specifically, or does any mid-session format change do it?
• Is the codec header dropped in flight, never sent, or processed out of order relative to
  the sink reconfigure?
• The two Lost sync events precede the chunk failures. Cause or symptom?
• Does the 4:1 resample matter? This host advertises rates up to 192 kHz because the
  PipeWire node reports them, but the HDMI sink runs at 48 kHz, so every hi-res stream is
  downsampled by the graph anyway. CPU went 0.6% -> 3.3% across the change.

Reproduction

Not yet reduced to reliable steps -- observed once, on a Music Assistant queue that moved
from a 48 kHz/16-bit track to a 192 kHz/24-bit track mid-session. Worth trying a queue
deliberately alternating sample rates.

[chrisuthe]

Full player log from the run in the report, attached before the host loses /tmp.

Captured with -o pipewire on the Pi 5 described above, from process start through the
failure, the manual pause/play, and several clean streams afterwards. The only edits: the
PortAudio/JACK/avahi-compat startup chatter on stderr is stripped (3 lines, none of it
from this player), and the Music Assistant server_id is replaced with <redacted>.
Otherwise verbatim, in order.

The interesting region is the second Stream started -- sink opens at 192 kHz/24-bit and
no Processed new codec header follows it, unlike every other stream open in the file.

player.log (111 lines)

I cli: No config file found; every option came from the command line or a built-in default
I control: Listening on /run/user/1000/sendspin-cli-8928.sock
I audio: -o pipewire is the native pipewire backend, not ALSA's plugin PCM of the same name -- write -o alsa:pipewire for that
I audio: Advertising 65 formats for 'pipewire': FLAC 2ch 16/24/32/8-bit @ 48000/44100/96000/88200/192000/176400/32000/22050 Hz; OPUS 2ch 16-bit @ 48000 Hz; PCM 2ch 16/24/32/8-bit @ 48000/44100/96000/88200/192000/176400/32000/22050 Hz
I cli: sendspin-cli 0.1.4 listening on port 8928 as "Pi-PipeWire-Test" (output: pipewire, mDNS: dns_sd (avahi-compat))
I sendspin.ws_server: Starting server on port: 8928 (max connections: 4)
I mdns: advertising _sendspin._tcp. as "Pi-PipeWire-Test" on port 8928 (path /sendspin)
I sendspin.conn_mgr: Connection handshake complete: server_id=<redacted>, connection_reason=discovery
I player: Static delay set to 0 ms by the server
I sendspin.conn_mgr: Handoff decision: keep current server
I player: Stream started
I audio: pipewire: 'pipewire' open at 48000 Hz, 2 ch, 16-bit (4 bytes/frame, 19201-byte ring)
I sendspin.sync_task: Processed new codec header: flac, 48000 Hz, 2 ch, 16-bit
I metadata: Now playing: Ed Sheeran - Perfect
I player: Static delay set to 0 ms by the server
I player: Stream started
I audio: pipewire: 'pipewire' open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
W sendspin.sync_task: Lost sync (43890us off), reporting error
I sendspin.sync_task: Regained sync, reporting synchronized
W sendspin.sync_task: Lost sync (64710us off), reporting error
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
W sendspin.player: Failed to send audio chunk
I player: Stream ended
I metadata: Now playing: Ed Sheeran - Perfect
I metadata: Now playing: Ed Sheeran - Perfect
I player: Stream started
I audio: pipewire: 'pipewire' open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
I sendspin.sync_task: Processed new codec header: flac, 192000 Hz, 2 ch, 24-bit
I sendspin.sync_task: Processed new codec header: flac, 192000 Hz, 2 ch, 24-bit
I player: Stream ended
I player: Stream started
I audio: pipewire: 'pipewire' open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
I sendspin.sync_task: Processed new codec header: flac, 192000 Hz, 2 ch, 24-bit
I metadata: Now playing: Doors - The Changeling
I metadata: Now playing: Doors - Love Her Madly
I metadata: Now playing: Doors - Love Her Madly
I player: Stream ended

A couple of things the full log adds over the excerpt in the report:

• The failing stream was preceded by Static delay set to 0 ms by the server, exactly as
  the first (working) stream was, so nothing looks different on the server's side going in.
• After recovery the player handled three further stream open/close cycles at
  192 kHz/24-bit and two track changes (Doors - The Changeling, Doors - Love Her Madly)
  with no warnings at all, so whatever went wrong did not leave the sink or the connection
  in a degraded state -- it was confined to that one stream.
• Advertising 65 formats is worth noting for the resample question: this player offers
  every rate the PipeWire node reports, up to 192 kHz, while the HDMI sink underneath runs
  at 48 kHz.

[chrisuthe]

Second reproduction -- deliberate, and cleaner than the first

Reproduced on purpose by switching the queue across a sample-rate boundary mid-session
(48 kHz/16-bit -> 192 kHz/24-bit), on -o pipewire, merged binary 52d0f2c8, same Pi 5 /
Debian 13 / libpipewire 1.4.2 host. A baseline was recorded immediately before the switch so
everything below is attributable to it: 8m40s of playback, 1 stream open, 1 codec header,
0 warnings of any kind.

After the switch:

I metadata: Now playing: blink-182 - MORE THAN YOU KNOW
I player: Static delay set to 0 ms by the server
I player: Stream started
I audio: pipewire: 'pipewire' open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
W sendspin.player: Failed to send audio chunk
   ... x329 and climbing ...

The diagnostic from the original report holds exactly:

stream opens  : 2
codec headers : 1

Why this capture is more useful than the first

There are no Lost sync events at all this time -- the first sighting had two, which left
open whether the desync caused the chunk failures. Here there is no sync error whatsoever and
chunks still fail 329 times, so the missing codec header is sufficient on its own. This also
separates this issue cleanly from #32, which is a different fault.

Everything below the codec header is provably healthy. State captured live, while broken,
rather than after recovery:

Check	Value
Sink opened at	192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)
pw-top client node	6400 @ 192000 S24LE, ERR 0
pw-top HDMI sink	1024 @ 48000 S32P, ERR 0
Sink-input sample spec	s24le 2ch 192000Hz
sendspin-cli status	output: pipewire (192000 Hz / 2 ch / 24-bit), state: playing, stream: receiving
audio:-tag warnings	0
Ring starvation warnings	0

So the output backend reconfigured correctly to the new format, the graph is running that
format with zero xruns, the sink-input matches, and the player's own status agrees. The ring
was resized correctly too: 115201 B / 6 B-per-frame = 19200 frames = 100 ms at 192 kHz, same
as it was 100 ms at 48 kHz before the switch.

Nothing in the audio path is broken. The failure is entirely that the decode path was never
given a codec header for the format the sink is now running.

Trigger

Both sightings are the same transition: 48 kHz/16-bit -> 192 kHz/24-bit, mid-session, on
-o pipewire. Whether other rate pairs or the other backends do it is still untested --
open question 1 in the original report stands.

Recovery

Unchanged from the first sighting: it does not self-recover, and a manual pause/play clears
it by forcing a fresh stream that does get a codec header.

[chrisuthe]

Third reproduction: it is NOT the 4x jump -- any format change does it

Open question 1 from the report is answered. Switched mid-session from 192 kHz/24-bit ->
44.1 kHz/16-bit: downward, non-integer ratio (4.35x), and a bit-depth change as well. It
fails the same way.

stream opens  : 4
codec headers : 3

All four opens this session, with the failures marked:

open at  48000 Hz, 2 ch, 16-bit (4 bytes/frame,  19201-byte ring)   header ok
open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)   header MISSING  <- 48k -> 192k
open at 192000 Hz, 2 ch, 24-bit (6 bytes/frame, 115201-byte ring)   header ok       <- pause/play recovery
open at  44100 Hz, 2 ch, 16-bit (4 bytes/frame,  17641-byte ring)   header MISSING  <- 192k -> 44.1k

So the trigger is the mid-session transition itself, not the ratio and not the direction.
That widens this issue considerably: 44.1 <-> 48 kHz is the most common boundary in a mixed
library, so ordinary queues will hit it.

Note also that the recovery stream (third open) is at the same format that had just
failed and succeeds. The format is not being rejected -- only the transition loses the
header.

Symptom this time: brief noise, then total silence

Reported audibly as "bad noises and is now silence". The capture shows two distinct
mechanisms rather than one:

Check	Value
Sink opened at	44100 Hz, 2 ch, 16-bit (4 bytes/frame, 17641-byte ring)
Client node in graph	1470 @ 44100 S16LE, ERR 0
HDMI sink	1024 @ 48000 S32P, ERR 1
Sink-input	present, s16le 2ch 44100Hz, Corked: no, Mute: no, 100% / 0.00 dB
Failed to send audio chunk	1848
Ring starvation warnings	0
Lost sync	1

The single xrun on the HDMI sink is new -- every previous capture in this issue and in
#32 showed ERR 0 everywhere. That accounts for the momentary noise, as the graph rebuilt its
resampler for 44.1 kHz against a 48 kHz driver. The silence that follows is the separate,
already-known failure: with no codec header, 1848 chunks fail to place and the graph renders
an empty stream faithfully.

The ring was sized correctly again (17641 B / 4 = 4410 frames = 100 ms at 44.1 kHz) and no
starvation warning fired, correctly, since 4410 frames easily holds the 1470-frame quantum.
Ring sizing has now been observed correct across four distinct formats.

The failure is invisible to monitoring

While completely silent, the control socket still reports:

state: playing
stream: receiving
position: 0:44 / 2:40 (estimated)
output: pipewire (44100 Hz / 2 ch / 16-bit)

The player believes it is playing. Anything watching the control socket -- a health check, a
dashboard, a group-sync supervisor -- would see a healthy player emitting nothing. Worth
considering whether a sustained run of Failed to send audio chunk should surface in the
player's own state rather than only in the log.

Also worth noting

Chunk failures kept accumulating for as long as the broken stream was left alone -- 329 when
first sampled in the previous reproduction, 1589 by the time it was recovered. It is not a
transient that settles; it is dead air until something intervenes.

Environment unchanged from the previous comment: merged binary 52d0f2c8, -o pipewire,
Pi 5 / Debian 13 / libpipewire 1.4.2, Music Assistant, HDMI sink at 48 kHz.