Fix ALSA playback clock after device recovery

[iibaranov-IG]

Fixes #54.

What goes wrong

While an ALSA device is absent, AlsaAudioSink::write() deliberately returns the discarded byte count so the Sendspin sync task does not spin. The sync task therefore adds every discarded frame to buffered_frames.

Before this change, nothing retired those frames. When the reopened PCM accepted its first real write, the normal playback callback combined the new ALSA finish timestamp with the entire outage-sized backlog. After the reporter's 14-second gap at 48 kHz, that projected the playhead 672,000 frames into the future. The resulting hard-sync cycle matches the reported short writes, XRUNs, and alternating Lost sync / Regained sync messages.

What changes

SinkRecovery keeps a saturating count of the frames discarded during an outage.

That count is retired by the first write() after recovery that gets a real device timestamp. It takes the count under device_mutex_, together with the snd_pcm_delay() reading, and then fires a single on_frames_played(gap + frames_done, finish_us) after unlocking, saturating at UINT32_MAX. A write that gets no timestamp leaves the count pending.

poll() never reports the gap itself. Reporting it there — after releasing the mutex — would let the sync task's first real write report ahead of it, which both reintroduces the outage-sized backlog on that first timestamp and can deliver timestamps out of order. Because the gap now travels with the write, there is no second callback to race, and the timestamp the player keeps is the device's own finish time rather than a wall-clock reading. poll() keeps its original structure.

Two narrower leaks are closed with it:

• The count is dropped in clear(), before its null-PCM early return, and at the top of configure(), so it goes whether or not the open succeeds. A gap from an ended or reconfigured stream can no longer be retired against the next one. Neither call refills the recovery budget, which stays reset()'s job.
• Frames that snd_pcm_writei() accepted before recover_() closed the device in the same write() call are added to the count. write() returns those bytes, but no timestamp would ever have reported them.

Tests

22 SinkRecovery tests, including the report's 14 seconds at 48 kHz retired exactly once, saturation instead of wrapping, the gap surviving a recovered rescan until a timed write takes it, dropping the gap leaving both a live and a spent budget untouched, and reset() clearing it.

Verification

• Clean build with -DSENDSPIN_CLI_WERROR=ON and ALSA, Pulse and PipeWire enabled, against the v0.8.0 library pin; full suite 434/434.
• CI green on c5b5279: shellcheck, clang-format, and builds for linux-x86_64, x86_64-nomdns, x86_64-pipewire-min, armv7, arm64 and macos-arm64.
• Hardware replug test on the reporter's OpenWrt box, run on a6b1c23; everything merged since is comment and formatting only (full report in the comments): playback resumes on its own with no XRUN loop and no sync cycling. The PCM stayed RUNNING across 144 samples and hw_ptr advanced continuously for about 5 minutes after recovery, in the same process. The reopen attempts landed 2 s, 4 s and 8 s after the loss, matching SINK_RESCAN_DELAY_MS and its doubling.

Recovery still costs one bounded realignment: the playhead is correct at reopen, but the audio the sink swallowed during the outage included the pipeline's lookahead, so the next chunk is not due yet and the sync task reports one error and fills silence until the timeline catches up. That is tracked separately in #63.

Compatibility

Nothing breaks for CLI users. No flags, config-file keys, control-socket protocol, state-store format or exit codes change, and no default moves. The only behaviour change is confined to an ALSA device that dies mid-stream: the frames discarded during the outage are now reported as played once the device is back, so the player's playback clock is no longer projected forward by the length of the outage.

The same discard-without-retire path exists in the Pulse, PortAudio and PipeWire sinks and is tracked in #58.

[Copilot]

🟡 Changes recommended

Playback accounting remains vulnerable to callback ordering, stream flushes, and partial writes during device loss.

Get a fresh assessment by requesting another Copilot review.

Pull request overview

Fixes ALSA playback-clock drift after device recovery by retiring frames discarded during outages.

Changes:

• Adds saturating discarded-frame accounting.
• Reports discarded frames after ALSA recovery.
• Adds gap and overflow unit tests.

File summaries

File	Description
src/alsa_sink.cpp	Tracks and reports discarded ALSA frames.
src/sink_recovery.cpp	Implements saturating frame accounting.
src/sink_recovery.h	Declares discarded-frame state and APIs.
tests/sink_recovery_test.cpp	Tests one-time reporting and saturation.

Review details

Suppressed comments (1)

src/alsa_sink.cpp:618

• Accounting only in the already-closed-device branch misses frames accepted earlier in a write() call that later detects device loss. In that case frames_done is returned to the producer, but the normal callback is skipped because recover_() closed pcm_; those frames remain permanently buffered even after this gap is retired. When a write exits because recovery closed the device, add its already-written frames_done to the discarded count as well.

            const size_t consumed = (frame == 0) ? length : length - (length % frame);
            if (frame != 0) {
                this->recovery_.discard_frames(static_cast<uint32_t>(consumed / frame));
            }

• Files reviewed: 4/4 changed files
• Comments generated: 2
• Review effort level: Balanced

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[chrisuthe]

I pushed two commits on top of Igor's fix that address the Copilot review. The outage gap is now retired together with the first real device timestamp instead of from poll(). It is also dropped when a stream ends or reconfigures, and frames written just before the device drops out are counted too.

@mguaylam, could you rerun your test from #54 with this branch on the OpenWrt box? Start playback, unplug the USB DAC, plug it back in, and check that:

• playback resumes on its own;
• there is no XRUN loop;
• the log shows no Lost/Regained sync cycling after recovery.

I'm keeping this PR in draft until that hardware test passes. The same gap in the Pulse, PortAudio and PipeWire sinks is tracked in #58.

[chrisuthe]

Also big thank you to @iibaranov-IG for jumping in! Appreciate the energy and contribution!

[mguaylam]

Tested on the OpenWrt box from #54. Playback resumes on its own, with no XRUN loop and no sync cycling.

Setup

The host is a plain home router, a D-Link DIR-3040 (MediaTek MT7621AT, dual-core MIPS at 880 MHz, no FPU, 256 MB RAM), with the DAC on one of its USB ports. It routes and serves WiFi while playing.

Build	PR head a6b1c23, packaged for OpenWrt (sendspin-cpp v0.7.2)
Host	OpenWrt 25.12.5, ramips/mt7621 (MIPS32 little-endian, musl), kernel 6.12.94
Output	-o hw:0,0 --buffer-ms 100 (4800-frame ring, 960-frame period)
Sink	generic USB Audio Class 1 adapter, S16_LE 2 ch 48000 Hz only
Server	Music Assistant, FLAC 48 kHz/16-bit

My OpenWrt package normally works around this bug by restarting the player when a playback device appears. That workaround was moved out of the way for this test, so the recovery below is this branch's alone.

What happened: playing, DAC unplugged at 00:09:40, plugged back in at 00:09:54.

00:09:40 E audio: alsa: 'hw:0,0' is gone (No such device)
00:09:40 E audio: alsa: 'hw:0,0' is not open -- discarding audio until it is back or a stream reconfigures it
00:09:42 E audio: alsa: cannot open 'hw:0,0': No such file or directory
00:09:46 E audio: alsa: cannot open 'hw:0,0': No such file or directory
00:09:54 I audio: alsa: 'hw:0,0' open at 48000 Hz, 2 ch, 16-bit (4 bytes/frame, 4800-frame ring, 960-frame period)
00:09:54 I audio: alsa: 'hw:0,0' is back -- recovered without waiting for the next stream
00:09:54 W sendspin.sync_task: Lost sync (10840302us off), reporting error
00:10:05 I sendspin.sync_task: Regained sync, reporting synchronized

Nothing after that: no underrun, no further sync message, and audio was audible and steady.

/proc/asound/card0/pcm0p/sub0/status, sampled every 2 s:

• 144 samples over the ~5 minutes after recovery, every one of them RUNNING; no XRUN, no PREPARED.
• hw_ptr went from 164,160 to 14,204,640, i.e. 292 s of audio, continuously.
• The player's pid never changed, so this is the same process recovering.

For contrast, on v0.1.6 the same sequence left hw_ptr stuck at 3840 frames with XRUN and PREPARED alternating about every 14 s, and Lost sync / Regained sync repeating until the player was restarted.

One observation, not a blocker: a single Lost sync (10840302us off) is reported the moment the device reopens, about 10.8 s for a ~14 s outage, and clears 11 s later. Is one hard resync expected here, with the retired gap making it a single event rather than a loop, or should the correction land early enough that the sync task never reports an error?

Happy to rerun anything, including a longer outage or a second replug during the same stream.

[chrisuthe]

Thanks — and that's normal. At reopen the playhead is correct, but the sink swallowed the pipeline's lookahead during the outage, so the next chunk isn't due for ~10.8 s. The sync task reports that once and fills silence until the timeline
catches up, which is why it cleared 11s later I'm pretty sure.

We may be able to do better by pacing the discard during an outage so the lookahead survives & I opened #63 for that.

If you have time: try unplugging and replugging twice in the same stream. That path uses the remaining retry budget and retires a second gap, which your run didn't reach.

[mguaylam]

Second replug tested on the same DIR-3040, now on head c5b5279 (sendspin-cpp v0.8.0), same setup as my previous comment, with my package's workaround out of the way again.

First outage recovers, second one never does.

19:29:34 I player: Stream started
19:29:34 I audio: alsa: 'hw:0,0' open at 48000 Hz, 2 ch, 16-bit (4 bytes/frame, 4800-frame ring, 960-frame period)
19:31:00 E audio: alsa: 'hw:0,0' is gone (No such device)
19:31:02 E audio: alsa: cannot open 'hw:0,0': No such file or directory
19:31:06 E audio: alsa: cannot open 'hw:0,0': No such file or directory
19:31:14 I audio: alsa: 'hw:0,0' open at 48000 Hz, 2 ch, 16-bit (4 bytes/frame, 4800-frame ring, 960-frame period)
19:31:14 I audio: alsa: 'hw:0,0' is back -- recovered without waiting for the next stream
19:31:14 W sendspin.sync_task: Lost sync (5941830us off), reporting error
19:31:20 I sendspin.sync_task: Regained sync, reporting synchronized
19:32:10 E audio: alsa: 'hw:0,0' is gone (No such device)
19:32:10 E audio: alsa: 'hw:0,0' is not open -- discarding audio until it is back or a stream reconfigures it

The first cycle is what you designed for: one Lost sync of 5.9 s for a 14 s outage, cleared 6 s later, and the gap retired once.

After the second unplug there is nothing at all: no cannot open retry, no reopen. The DAC re-enumerated 30 s later (kernel log), /proc/asound/card0 is back, but /proc/asound/card0/pcm0p/sub0/status stayed closed/absent from 19:32:10 until I restarted the player, while sendspin-cli status still reported state: playing and stream: receiving. Silent output, the same stream still running.

Reading sink_recovery.cpp at this head, that looks like the budget being spent by success rather than by attempts:

• handle_device_loss_() calls reopen_due(), which for a second outage finds reopen_spent_ and goes to escalate_();
• escalate_() only owes a rescan if (!rescan_spent_ && !rescan_in_flight_);
• rescan_done(true) set rescan_spent_ = true when the first outage recovered, and only reset(), called from configure(), clears it.

So the four remaining rescans of SINK_RESCAN_ATTEMPTS are unreachable within the same configured stream, and the sink stays closed until a new stream reconfigures it.

This is not something this PR introduced: the same rescan_done(true) path is in v0.1.6. Would it make sense for a successful rescan to return the budget, clearing rescan_spent_ and zeroing rescan_attempts_, so that every outage in a stream gets its own reopen and rescans? I am happy to test that, or to open a separate issue if you prefer to keep this PR to the clock fix.

[chrisuthe]

Lets open a new issue, and keep that conversation going @mguaylam