From 282dab43eb4e829d64a33062f515e8ba5f73e546 Mon Sep 17 00:00:00 2001 From: Caleb Allen Date: Wed, 19 Aug 2026 09:05:55 -0400 Subject: [PATCH 1/3] fix(player): end the stream when the audio source stops producing BufferedStreamer.Stream treated an empty ring buffer as a momentary underrun and answered with silence and ok. That is right while the read-ahead is still going to deliver something, and two of its three exit paths left it never going to: a Close, and a source returning (0, true) in a loop. Neither set done, so the ring drained and every call after it was silence claiming to be audio, for the life of the process. Nothing above this type could tell that from healthy playback. The beep.Seq chain never ended, so the player stayed in Playing with the button showing pause; the decoder's position never moved, so the 1 Hz report pinned the seek bar at a constant -- and since every report resets the bar's interpolation, the report actively suppressed the one thing that would still have moved it. A frozen bar over a track that was not playing, with no watchdog anywhere to notice. Every exit now marks the stream done, and the silence fill is bounded by a duration *and* a run of calls. It needs both. Wall clock is the real measure, because the speaker paces itself and a stall is a question about time -- but a caller draining in a tight loop makes hundreds of calls in microseconds and would outrun a duration alone. A call count alone is the opposite failure, and not a hypothetical one: the first attempt used one and spent the whole budget before the read-ahead goroutine had been scheduled once, ending a perfectly good stream at sample zero and breaking TestBufferedStreamer_BasicStream. Err is plumbed out at the same time, because a drained source and a failed one both arrive as (0, false) and are not the same event. Reading it is a separate change; without it there is nothing to read. Closes #122 --- backend/player/buffered_stall_test.go | 188 ++++++++++++++++++++++++++ backend/player/buffered_streamer.go | 122 +++++++++++++++-- 2 files changed, 301 insertions(+), 9 deletions(-) create mode 100644 backend/player/buffered_stall_test.go diff --git a/backend/player/buffered_stall_test.go b/backend/player/buffered_stall_test.go new file mode 100644 index 0000000..3dbc7cc --- /dev/null +++ b/backend/player/buffered_stall_test.go @@ -0,0 +1,188 @@ +package player + +import ( + "errors" + "testing" + "time" + + "github.com/gopxl/beep/v2" +) + +// errTestDecode stands in for a decoder blowing up mid-track. +var errTestDecode = errors.New("decode blew up") + +// stalledStreamer never produces a sample and never reports +// end-of-stream: (0, true), forever. A damaged file that decodes to +// nothing looks like this, and so does any source whose producer has +// quietly stopped. +type stalledStreamer struct{} + +func (stalledStreamer) Stream(_ [][2]float64) (int, bool) { return 0, true } +func (stalledStreamer) Err() error { return nil } + +// failingStreamer produces n good samples and then fails, which is +// what a decode error mid-track looks like: the same (0, false) a +// finished track returns, distinguishable only by Err. +type failingStreamer struct { + remaining int + err error +} + +func (f *failingStreamer) Stream(samples [][2]float64) (int, bool) { + if f.remaining <= 0 { + return 0, false + } + + n := min(len(samples), f.remaining) + + for i := range n { + samples[i] = [2]float64{1, 1} + } + + f.remaining -= n + + return n, true +} + +func (f *failingStreamer) Err() error { return f.err } + +// drainUntilEnd calls Stream until it reports end-of-stream, or gives +// up. It returns whether the stream ended. +// +// The give-up bound is wall clock rather than a call count: the stall +// budget is a duration, so a tight loop has to actually wait it out. +func drainUntilEnd(bs *BufferedStreamer, within time.Duration) bool { + buf := make([][2]float64, 512) + deadline := time.Now().Add(within) + + for time.Now().Before(deadline) { + if _, ok := bs.Stream(buf); !ok { + return true + } + + time.Sleep(time.Millisecond) + } + + return false +} + +// A source that stops producing without ever ending is the fault this +// whole file exists for: Stream used to answer with silence and ok +// forever, so the chain never ended, the player stayed in Playing +// with the button showing pause, and the decoder's position never +// moved -- a frozen seek bar over a track that was not playing. +func TestAStalledSourceEndsTheStream(t *testing.T) { + bs := NewBufferedStreamer(stalledStreamer{}, 2048) + defer bs.Close() + + if !drainUntilEnd(bs, maxStarvedDuration+2*time.Second) { + t.Fatal( + "a stalled source never ended the stream: the player " + + "would sit in Playing with a frozen position", + ) + } + + if !errors.Is(bs.Err(), errSourceStalled) { + t.Fatalf( + "expected the stall to be reported, got %v", bs.Err(), + ) + } +} + +// Close is the other exit that used to leave `done` false, with the +// same consequence: the ring drains and every call after it is +// silence that claims to be audio. +func TestClosingEndsTheStream(t *testing.T) { + bs := NewBufferedStreamer(finiteStreamer(1<<20), 2048) + + // Let the read-ahead fill something, so this exercises the drain + // after Close rather than a buffer that was empty anyway. + time.Sleep(20 * time.Millisecond) + bs.Close() + + if !drainUntilEnd(bs, 2*time.Second) { + t.Fatal("a closed streamer never reported end-of-stream") + } +} + +// A source that fails is not a source that finished, and only Err +// tells them apart. Before this, the player reported a mid-track +// decode failure to the queue as a natural end, so the queue +// auto-advanced in silence and counted the broken track as played. +func TestAFailedSourceReportsItsError(t *testing.T) { + src := &failingStreamer{remaining: 4096, err: errTestDecode} + + bs := NewBufferedStreamer(src, 2048) + defer bs.Close() + + if !drainUntilEnd(bs, 2*time.Second) { + t.Fatal("a failing source never reported end-of-stream") + } + + if !errors.Is(bs.Err(), errTestDecode) { + t.Fatalf( + "expected the source's error to survive, got %v", + bs.Err(), + ) + } +} + +// The ordinary case has to keep working: a source that ends cleanly +// ends with no error, or every finished track would be reported as a +// failure and skipped. +func TestADrainedSourceReportsNoError(t *testing.T) { + bs := NewBufferedStreamer(finiteStreamer(4096), 2048) + defer bs.Close() + + if !drainUntilEnd(bs, 2*time.Second) { + t.Fatal("a finite source never reported end-of-stream") + } + + if bs.Err() != nil { + t.Fatalf( + "a track that finished normally reported %v", bs.Err(), + ) + } +} + +// A slow source is exactly what the read-ahead exists to absorb, so +// underruns must not be charged cumulatively -- otherwise a file on a +// slow disk ends itself partway through. +func TestUnderrunsDoNotAccumulateAcrossASlowSource(t *testing.T) { + const total = 8192 + + src := &slowStreamer{ + inner: finiteStreamer(total), + delay: 2 * time.Millisecond, + } + + bs := NewBufferedStreamer(src, 1024) + defer bs.Close() + + buf := make([][2]float64, 256) + got := 0 + + for { + n, ok := bs.Stream(buf) + if !ok { + break + } + + for i := range n { + if buf[i][0] != 0 { + got++ + } + } + } + + if got != total { + t.Fatalf( + "a slow but healthy source was cut short: got %d of %d "+ + "samples", + got, total, + ) + } +} + +// beep.Streamer is what the player wraps; keep the type honest. +var _ beep.Streamer = (*BufferedStreamer)(nil) diff --git a/backend/player/buffered_streamer.go b/backend/player/buffered_streamer.go index f9e01cf..993286e 100644 --- a/backend/player/buffered_streamer.go +++ b/backend/player/buffered_streamer.go @@ -1,6 +1,7 @@ package player import ( + "errors" "sync" "time" @@ -34,8 +35,45 @@ type BufferedStreamer struct { done bool err error closed chan struct{} + + // starved counts consecutive Stream calls served with silence + // because the ring was empty, and starvedSince is when that run + // began. An underrun is legitimate for a moment -- that is what + // the read-ahead exists to absorb -- but it is not legitimate + // forever, and "forever" is indistinguishable from healthy + // playback everywhere above this type: the chain never ends, so + // the player stays in Playing with the button showing pause, and + // the decoder's position never moves, so the 1 Hz report pins the + // seek bar and suppresses its interpolation. + starved int + starvedSince time.Time } +// The silence fill is bounded by both a duration and a run of calls, +// and it needs both. +// +// Duration alone is the real measure -- the speaker paces itself, so +// wall clock is what says whether the source has actually stopped -- +// but a caller draining in a tight loop (a test, a decode-to-buffer) +// makes hundreds of calls in microseconds and would trip nothing. +// A call count alone is the opposite failure: the same tight loop +// spends the whole budget before the read-ahead goroutine has been +// scheduled once, and ends a perfectly good stream at sample zero. +// +// The duration is longer than the 2 s read-ahead it is there to +// outlast, and the count is short enough that the speaker (~200 ms a +// call) reaches it well inside that. +const ( + maxStarvedDuration = 3 * time.Second + minStarvedCalls = 8 +) + +// errSourceStalled is returned by Err when the source stopped +// producing samples without ever reporting end-of-stream. +var errSourceStalled = errors.New( + "audio source stopped producing samples", +) + // NewBufferedStreamer creates a BufferedStreamer that pre-fills // bufferSize samples from source via a background goroutine. // A typical bufferSize is 2× the sample rate (~2 seconds of audio). @@ -54,8 +92,24 @@ func NewBufferedStreamer( return bs } +// finish marks the stream ended, recording err as the reason when +// there is one. Every exit from readAhead goes through it: an exit +// that leaves done false strands Stream in its underrun branch, +// where it returns silence and ok forever. +func (bs *BufferedStreamer) finish(err error) { + bs.mu.Lock() + defer bs.mu.Unlock() + + bs.done = true + + if err != nil && bs.err == nil { + bs.err = err + } +} + // readAhead continuously reads from the source into the ring buffer // until the source is drained, an error occurs, or Close is called. +// It always marks the stream done on the way out. func (bs *BufferedStreamer) readAhead() { // Temporary buffer for reading from source outside the lock. // 512 samples per chunk keeps the critical section short. @@ -63,6 +117,13 @@ func (bs *BufferedStreamer) readAhead() { tmp := make([][2]float64, chunkSize) + // Every exit marks the stream done. An exit that does not is what + // stranded Stream in its underrun branch, returning silence and ok + // for the rest of the process's life. + var exitErr error + + defer func() { bs.finish(exitErr) }() + for { // Check if closed. select { @@ -72,6 +133,15 @@ func (bs *BufferedStreamer) readAhead() { } bs.mu.Lock() + + // Stream gave up waiting for us. Nothing downstream is + // listening any more, so filling the ring is work for nobody. + if bs.done { + bs.mu.Unlock() + + return + } + space := len(bs.ring) - bs.count if space == 0 { @@ -115,14 +185,12 @@ func (bs *BufferedStreamer) readAhead() { } if !ok { - bs.mu.Lock() - bs.done = true - - if srcErr := bs.source.Err(); srcErr != nil { - bs.err = srcErr - } - - bs.mu.Unlock() + // A drained source and a failed one both land here and are + // not the same event: one is a track that ended, the other + // is a track that broke. Err is what tells them apart, and + // it is why the player must ask before treating this as a + // natural finish. + exitErr = bs.source.Err() return } @@ -154,7 +222,27 @@ func (bs *BufferedStreamer) Stream( } if bs.count == 0 { - // Buffer temporarily empty — fill with silence. + // The read-ahead has not caught up. Silence buys it time -- + // but only for a bounded stretch, because "forever" is + // reported upward as healthy playback and there is no watchdog + // above this to notice otherwise. + bs.starved++ + + if bs.starvedSince.IsZero() { + bs.starvedSince = time.Now() + } + + if bs.starved >= minStarvedCalls && + time.Since(bs.starvedSince) > maxStarvedDuration { + bs.done = true + + if bs.err == nil { + bs.err = errSourceStalled + } + + return 0, false + } + for i := range samples { samples[i] = [2]float64{} } @@ -162,6 +250,9 @@ func (bs *BufferedStreamer) Stream( return len(samples), true } + // Samples arrived, so whatever the stall was, it is over. + bs.resetStarvationLocked() + // Copy available samples from ring buffer. n := len(samples) if n > bs.count { @@ -197,6 +288,19 @@ func (bs *BufferedStreamer) Flush() { bs.readPos = 0 bs.writPos = 0 bs.count = 0 + + // A seek empties the ring on purpose, and the refill that follows + // is exactly the stall the budget exists to tolerate. Charging it + // against a budget the previous underrun already spent would end + // the track on a seek near the end of a slow file. + bs.resetStarvationLocked() +} + +// resetStarvationLocked forgets an underrun run. Must be called with +// bs.mu held. +func (bs *BufferedStreamer) resetStarvationLocked() { + bs.starved = 0 + bs.starvedSince = time.Time{} } // LockSource blocks the read-ahead goroutine from touching the -- 2.54.0 From 2b84bc53e9f7864d46b68221f5ee284dac498178 Mon Sep 17 00:00:00 2001 From: Caleb Allen Date: Wed, 19 Aug 2026 09:06:22 -0400 Subject: [PATCH 2/3] fix(player): stop reporting one track's state against another Five faults found while auditing the play/pause and position path for a desktop report of the pause icon showing over a seek bar that was not moving. They are one commit because they are one file's worth of tangled state, and two of them do not compile apart. The finished callback did not know which chain it came from. It is dispatched as a goroutine from the beep callback and then queues for p.mu, so a user pressing Next in the last second of a track had it wake up holding the lock for a player that had loaded something else -- and rewind it, stop it, and hand a stale finish to the queue's auto-advance. updateStreamers now stamps a chainID and the callback carries the one it was registered with. (#123) It also emitted PlaybackFinished and PlaybackStateChanged(stopped) *after* releasing p.mu, alone in this file, so a Play() taking the lock in that gap emitted `playing` first and the stale `stopped` landed last -- the button showing play over a track that was audibly running. Both emits are back under the lock. (#123) A source that failed mid-track was reported to the queue as a natural end, so a broken file auto-advanced in silence and was counted as played. The handler takes the reason now: the player cannot name the track, because the metadata is the queue's, so the queue emits PlaybackFailed and skips recording the play. (#123) p.format was assigned once, in the constructor, to the *speaker's* rate, and never again -- so it claimed 44.1 kHz for every file. The replay-after-finish path resamples from it, meaning a finished track played a second time was resampled from a rate the decoder never produced: audibly wrong speed and pitch, and the length and position fallbacks wrong with it. The fixtures are 22050 Hz, which is what lets a test see this at all. (#124) p.trackLengthMs was written only when the database had a row and cleared only by UnloadTrack, so a file with no row inherited the previous track's duration -- and every position report is scaled by it, so the bar reported one track's progress on another's scale. (#125) Queue.OnPlaybackFinished indexed q.tracks[currentIndex] having checked only that the queue was non-empty. currentIndex is -1 whenever the queue has been exhausted, and onQueueExhausted deliberately leaves the finished track loaded -- so playing it from there and letting it end panicked, on a goroutine with no caller to recover it. (#126) The position readers guarded the decoder with the speaker lock, which the read-ahead goroutine has no reason to hold and never takes -- so Position() raced readAhead's Stream() on every position emit, once a second for the whole of playback. srcMu is the lock that excludes that goroutine, and taking it naively deadlocks, because seekLocked already holds it and then emits the landing position from inside that region. seekSourceLocked is that region extracted, so the lock is released before anything is emitted. Found by the race detector, via the test added here for the chain guard: the existing suite never loads a file outside the integration guard, so make test was green over it. (#127) OnPlaybackFinished picks up //wails:ignore along with its error parameter: v3's generator segfaults on a bound method taking an error, and this was never IPC. That removes a binding the frontend could have called to force an auto-advance. Closes #123 Closes #124 Closes #125 Closes #126 Closes #127 --- backend/player/loadstate_test.go | 213 ++++++++++++++++++ backend/player/player.go | 205 ++++++++++++++--- backend/queue/fallback_test.go | 6 +- backend/queue/finished_test.go | 78 +++++++ backend/queue/handlers.go | 45 +++- backend/queue/playbackfailed_test.go | 4 +- .../yellowjacket/backend/queue/queue.ts | 8 - 7 files changed, 503 insertions(+), 56 deletions(-) create mode 100644 backend/player/loadstate_test.go create mode 100644 backend/queue/finished_test.go diff --git a/backend/player/loadstate_test.go b/backend/player/loadstate_test.go new file mode 100644 index 0000000..50dabbd --- /dev/null +++ b/backend/player/loadstate_test.go @@ -0,0 +1,213 @@ +package player + +import ( + "log/slog" + "testing" + "time" + + "github.com/wailsapp/wails/v3/pkg/application" + + "yellowjacket/backend/events" + "yellowjacket/internal/testfixtures" +) + +// fixtureSampleRate is what cmd/gentestdata writes (audio.go). It is +// deliberately not the speaker rate, which is what lets these tests +// tell the decoder's format from the player's default. +const fixtureSampleRate = 22050 + +// newTestPlayer is a player with a context and no database, so the +// track-metadata lookup cannot succeed. +func newTestPlayer(t *testing.T) *Player { + t.Helper() + + p := NewPlayer(slog.Default(), nil) + rec := events.NewRecorder() + + _ = p.ServiceStartup( + events.WithSink(t.Context(), rec), + application.ServiceOptions{}, + ) + + return p +} + +// loadFileLocked needs no speaker: it decodes, builds the chain and +// registers it paused. speaker.Play on an uninitialised device is +// what the integration guard elsewhere is about, so these assert on +// the state the load computed rather than on playback. + +// p.format used to be assigned once, in the constructor, to the +// *speaker's* rate -- so it claimed 44.1 kHz for every file ever +// loaded. Play()'s replay-after-finish path resamples from it, so a +// finished track played again was resampled from a rate the decoder +// never produced: audibly the wrong speed and pitch, and wrong +// length and position arithmetic with it. +// +// The fixtures are 22050 Hz, which is exactly the point -- any of +// them disagrees with the speaker rate. +func TestLoadRecordsTheDecodersOwnFormat(t *testing.T) { + m := testfixtures.Load(t) + path := m.Case(t, testfixtures.CaseCoverDedup)[0] + + p := newTestPlayer(t) + + if got := p.format.SampleRate; got != speakerSampleRate { + t.Fatalf( + "precondition: a fresh player should hold the speaker "+ + "rate, got %d", + got, + ) + } + + if err := p.LoadFile(path); err != nil { + t.Fatalf("LoadFile(%s): %v", path, err) + } + + if p.format.SampleRate == speakerSampleRate { + t.Fatalf( + "p.format still holds the speaker rate (%d) after "+ + "loading a %d Hz file: the replay path would "+ + "resample from the wrong rate", + speakerSampleRate, fixtureSampleRate, + ) + } + + if got := int(p.format.SampleRate); got != fixtureSampleRate { + t.Errorf( + "expected the decoder's rate %d, got %d", + fixtureSampleRate, got, + ) + } +} + +// trackLengthMs is written only when the database has a row for the +// file and cleared only by UnloadTrack, so a track with no row used +// to inherit whatever the last track's duration was -- and every +// position report is scaled by it, so the whole seek bar was then +// reporting one track's progress on another track's scale. +// +// There is no database here, so the lookup cannot succeed: exactly +// the case that used to inherit. +func TestLoadDoesNotInheritThePreviousTracksDuration(t *testing.T) { + m := testfixtures.Load(t) + path := m.Case(t, testfixtures.CaseCoverDedup)[0] + + p := newTestPlayer(t) + + // Stand in for a previous track whose duration was resolved. + p.trackLengthMs = 9_999_000 + + if err := p.LoadFile(path); err != nil { + t.Fatalf("LoadFile(%s): %v", path, err) + } + + if p.trackLengthMs == 9_999_000 { + t.Fatal( + "the previous track's duration survived the load: every " + + "position report for this track would be scaled by it", + ) + } +} + +// A new chain supersedes the old one's pending finished callback. +// Without this, a callback that queued for p.mu behind a LoadFile +// woke up and rewound, stopped and auto-advanced the *new* track. +func TestANewChainSupersedesTheOldFinishedCallback(t *testing.T) { + m := testfixtures.Load(t) + paths := m.Case(t, testfixtures.CaseCoverDedup) + + if len(paths) < 2 { + t.Skip("need two fixture tracks") + } + + p := newTestPlayer(t) + + if err := p.LoadFile(paths[0]); err != nil { + t.Fatalf("LoadFile(%s): %v", paths[0], err) + } + + stale := p.chainID + + if err := p.LoadFile(paths[1]); err != nil { + t.Fatalf("LoadFile(%s): %v", paths[1], err) + } + + if p.chainID == stale { + t.Fatal("loading a second file did not supersede the chain") + } + + called := false + + p.SetPlaybackFinishedHandler(func(error) { called = true }) + + // The first track's callback, arriving late. + p.onPlaybackFinished(stale, nil) + + if called { + t.Error( + "a superseded chain's callback drove auto-advance: the " + + "track that is loaded now would be skipped", + ) + } + + if p.state == Stopped { + t.Error( + "a superseded chain's callback stopped the current track", + ) + } +} + +// The decoder is read by the read-ahead goroutine and by every +// position emit, and those used to be guarded by different mutexes: +// the read by srcMu, the position by the speaker lock, which +// read-ahead never takes. Under -race this failed on the emit that +// LoadFile itself makes. +// +// It needs the read-ahead goroutine to actually be running, so it +// keeps asking for the position for long enough to overlap it. +func TestPositionReadsDoNotRaceTheReadAhead(t *testing.T) { + m := testfixtures.Load(t) + path := m.Case(t, testfixtures.CaseFLACAlbum)[0] + + p := newTestPlayer(t) + + if err := p.LoadFile(path); err != nil { + t.Fatalf("LoadFile(%s): %v", path, err) + } + + for range 200 { + if _, err := p.CurrentPositionSeconds(); err != nil { + t.Fatalf("CurrentPositionSeconds: %v", err) + } + } +} + +// Seeking emits the landing position, and that emit reads the +// decoder -- so the source lock the seek holds must be released +// before it. A reentrant take here is a deadlock, not a failure, +// which is why this test exists rather than a comment. +func TestSeekEmitsWithoutDeadlocking(t *testing.T) { + m := testfixtures.Load(t) + path := m.Case(t, testfixtures.CaseFLACAlbum)[0] + + p := newTestPlayer(t) + + if err := p.LoadFile(path); err != nil { + t.Fatalf("LoadFile(%s): %v", path, err) + } + + done := make(chan struct{}) + + go func() { + defer close(done) + + _ = p.Seek(1) + }() + + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("Seek deadlocked: the position emit re-took the source lock") + } +} diff --git a/backend/player/player.go b/backend/player/player.go index b141a6d..7ff3b5c 100644 --- a/backend/player/player.go +++ b/backend/player/player.go @@ -52,9 +52,17 @@ type Player struct { control *beep.Ctrl volume *effects.Volume speakerStreamer beep.Streamer - playbackFinishedHandler func() + playbackFinishedHandler func(error) trackChangeID uint64 - mediaControls mediacontrols.Handler + + // chainID identifies the streamer chain currently registered with + // the speaker. updateStreamers bumps it, and the finished + // callback carries the value it was registered with, so a callback + // that queued for p.mu behind a LoadFile can tell that the player + // has moved on and return rather than rewinding somebody else's + // track. + chainID uint64 + mediaControls mediacontrols.Handler // duckAmount is the attenuation currently applied on top of the // user's volume, in the same base-2 exponent effects.Volume uses. @@ -180,11 +188,18 @@ func (p *Player) InitSpeaker() error { } // SetPlaybackFinishedHandler sets a callback invoked when a track -// finishes naturally. This allows the queue to drive auto-advance +// stops streaming. This allows the queue to drive auto-advance // without circular imports. // +// The error says *why* the track stopped: nil for a track that +// reached its end, non-nil for one that broke partway through. Both +// arrive here because both look identical to the speaker, and only +// the queue holds the metadata a PlaybackFailed needs -- but they are +// not the same event, and reporting a decode failure as a natural +// finish is how a broken file used to auto-advance in silence. +// //wails:ignore // internal wiring, not part of the app's IPC surface. -func (p *Player) SetPlaybackFinishedHandler(handler func()) { +func (p *Player) SetPlaybackFinishedHandler(handler func(error)) { p.mu.Lock() defer p.mu.Unlock() @@ -424,6 +439,19 @@ func (p *Player) updateStreamers( newBaseStreamer beep.StreamSeeker, sr beep.SampleRate, ) error { + // A new chain supersedes the old one, so any finished callback the + // old one still owes is stale from here on. + p.chainID++ + + // The previous read-ahead goroutine reads the same decoder this + // one is about to, under its own srcMu -- two goroutines, two + // mutexes, one decoder that is not safe for concurrent use. The + // replay-after-finish path rebuilds from p.seeker without going + // through LoadFile, which is where that pair could meet. + if p.buffered != nil { + p.buffered.Close() + } + // set base streamer p.baseStreamer = newBaseStreamer p.seeker = newBaseStreamer @@ -474,23 +502,57 @@ func (p *Player) startPaused() { p.control.Paused = true speaker.Unlock() + // Captured, not read at callback time: by then p.chainID names + // whatever is loaded *now*, which is the thing the guard exists to + // distinguish this chain from. + chainID := p.chainID + buffered := p.buffered + // The beep.Callback runs with the speaker mutex held, so we // dispatch to a goroutine that can safely acquire p.mu. speaker.Play(beep.Seq( p.speakerStreamer, beep.Callback(func() { - go p.onPlaybackFinished() + // Asked here rather than under p.mu: this is the chain that + // just ended, and by the time the goroutine holds the lock + // p.buffered may be a different one. + var err error + if buffered != nil { + err = buffered.Err() + } + + go p.onPlaybackFinished(chainID, err) }), )) p.state = Paused } -// onPlaybackFinished handles the natural end of a track. It is -// called on a new goroutine from the beep callback (which holds -// the speaker lock) so that it can safely acquire p.mu. -func (p *Player) onPlaybackFinished() { +// onPlaybackFinished handles a track that stopped streaming, whether +// it ended or broke. It is called on a new goroutine from the beep +// callback (which holds the speaker lock) so that it can safely +// acquire p.mu. +// +// chainID names the streamer chain the callback fired for and srcErr +// says why it stopped. +func (p *Player) onPlaybackFinished(chainID uint64, srcErr error) { p.mu.Lock() + + // The player has moved on while this callback queued for the lock + // -- a user pressing Next during the last second of a track is + // enough. Everything below is about the *current* track: rewinding + // the decoder, saying playback stopped, asking the queue to + // advance. Doing any of it now would do it to the wrong track. + if chainID != p.chainID { + p.mu.Unlock() + p.logger.Debug( + "Ignoring finished callback for a superseded chain", + "chain", chainID, "current", p.chainID, + ) + + return + } + p.state = Stopped handler := p.playbackFinishedHandler mc := p.mediaControls @@ -501,10 +563,11 @@ func (p *Player) onPlaybackFinished() { // the Stopped state anyway, so this only moves the decoder. p.rewindLocked() p.emitPositionLocked() - p.mu.Unlock() - // Emit Wails events outside the lock — these are non-blocking - // calls that don't need player state. + // Emitted under p.mu, like every other transition in this file. + // Outside it, a Play() taking the lock in the gap emits `playing` + // first and this stale `stopped` lands last -- leaving the button + // showing play over a track that is audibly running. p.emitPlaybackFinished() events.Emit( @@ -513,6 +576,8 @@ func (p *Player) onPlaybackFinished() { map[string]string{"state": string(Stopped)}, ) + p.mu.Unlock() + // Notify media controls outside the lock. The track just // ended so position is 0. if mc != nil { @@ -521,12 +586,19 @@ func (p *Player) onPlaybackFinished() { ) } - p.logger.Info("Playback finished naturally") + if srcErr != nil { + p.logger.Error( + "Playback stopped: the audio source failed", + "err", srcErr, + ) + } else { + p.logger.Info("Playback finished naturally") + } // Notify queue for auto-advance. Called without p.mu held // because it re-enters the player via LoadFile/Play. if handler != nil { - handler() + handler(srcErr) } } @@ -587,6 +659,18 @@ func (p *Player) loadFileLocked(filePath string) error { p.currentFile = f + // The decoder's own format, kept for the paths that rebuild the + // chain later: Play()'s replay branch resamples from it, so a + // stale rate there plays a finished track back at the wrong speed. + p.format = format + + // The previous track's duration must not outlive it. This is set + // again by emitTrackChanged below, but only when the database has + // a row for the file -- and every position this player reports is + // scaled by it, so inheriting means every report is wrong by the + // ratio between two unrelated tracks. + p.trackLengthMs = 0 + if err := p.updateStreamers( streamer, format.SampleRate, ); err != nil { @@ -906,6 +990,8 @@ func (p *Player) CurrentPosition() (int, error) { return 0, errNoAudioFileLoaded } + defer p.lockSourceLocked()() + speaker.Lock() pos := math.Round( 100.0 * float64(p.seeker.Position()) / @@ -924,6 +1010,28 @@ func (p *Player) Seek(targetSeconds int) error { return p.seekLocked(targetSeconds) } +// lockSourceLocked blocks the read-ahead goroutine from touching the +// decoder and returns the function that releases it, so a caller can +// `defer p.lockSourceLocked()()`. +// +// Reading the decoder's position is a read *of the decoder*, and the +// speaker lock does not exclude the read-ahead goroutine -- it never +// takes it. That was a genuine data race on every position emit, +// once a second for the whole of playback. +// +// srcMu is not reentrant, so nothing that already holds it may call +// this; seekSourceLocked exists to keep that region free of emits. +// Must be called with p.mu held. +func (p *Player) lockSourceLocked() func() { + if p.buffered == nil { + return func() {} + } + + p.buffered.LockSource() + + return p.buffered.UnlockSource +} + // rewindLocked returns the decoder to the start of the track without // touching playback state. Must be called with p.mu held. func (p *Player) rewindLocked() { @@ -959,6 +1067,46 @@ func (p *Player) seekLocked(targetSeconds int) error { return fmt.Errorf("cannot get track length: %w", err) } + // The source lock is released before anything below is emitted: + // emitPositionLocked reads the decoder's position and takes the + // same lock, which is not reentrant. + seekErr := p.seekSourceLocked(targetSeconds, lengthSecs) + if seekErr != nil { + p.logger.Warn( + "Seek failed, playback will start from "+ + "the beginning", + "target-seconds", targetSeconds, + "err", seekErr, + ) + + // The optimistic move the UI already made has to be taken + // back, and only the backend knows it did not happen. + events.Emit(p.ctx, events.SeekFailed) + p.emitPositionLocked() + + return fmt.Errorf("failed to seek: %w", seekErr) + } + + if p.mediaControls != nil { + p.mediaControls.NotifySeek(targetSeconds) + } + + // Report the landing position immediately rather than leaving the + // UI to guess until the next tick — this is the half of H-3 that + // desynced the seek bar by 30 s over four keyboard seeks. + p.emitPositionLocked() + + return nil +} + +// seekSourceLocked moves the decoder and flushes the stale read-ahead +// behind it. It owns the source lock for exactly that long and +// emits nothing, so its caller is free to read the position +// afterwards. Must be called with p.mu held. +func (p *Player) seekSourceLocked( + targetSeconds int, + lengthSecs int, +) error { // Block the read-ahead goroutine from reading the source while // we seek it. The decoder (e.g. FLAC's bufseekio.ReadSeeker) is // not safe for concurrent Read+Seek, and read-ahead runs on its @@ -1014,19 +1162,11 @@ func (p *Player) seekLocked(targetSeconds int) error { if seekErr != nil { speaker.Unlock() - p.logger.Warn( - "Seek failed, playback will start from "+ - "the beginning", - "target-seconds", targetSeconds, - "samples", samples, - "err", seekErr, + p.logger.Debug( + "seek rejected by the decoder", + "samples", samples, "err", seekErr, ) - // The optimistic move the UI already made has to be taken - // back, and only the backend knows it did not happen. - events.Emit(p.ctx, events.SeekFailed) - p.emitPositionLocked() - return fmt.Errorf("failed to seek: %w", seekErr) } @@ -1039,15 +1179,6 @@ func (p *Player) seekLocked(targetSeconds int) error { p.buffered.Flush() } - if p.mediaControls != nil { - p.mediaControls.NotifySeek(targetSeconds) - } - - // Report the landing position immediately rather than leaving the - // UI to guess until the next tick — this is the half of H-3 that - // desynced the seek bar by 30 s over four keyboard seeks. - p.emitPositionLocked() - return nil } @@ -1140,6 +1271,10 @@ func (p *Player) seekerLengthSecsLocked() (int, error) { return 0, errNoAudioFileLoaded } + // Len is fixed for the life of the decoder, so unlike Position it + // races with nothing and needs no source lock -- which it must not + // take anyway: displayPositionSecsLocked calls this while holding + // it, and srcMu is not reentrant. speaker.Lock() length := p.seeker.Len() / int(p.format.SampleRate) speaker.Unlock() @@ -1156,6 +1291,8 @@ func (p *Player) displayPositionSecsLocked() int { return 0 } + defer p.lockSourceLocked()() + speaker.Lock() pos := p.seeker.Position() total := p.seeker.Len() diff --git a/backend/queue/fallback_test.go b/backend/queue/fallback_test.go index 79585e2..901daa9 100644 --- a/backend/queue/fallback_test.go +++ b/backend/queue/fallback_test.go @@ -83,7 +83,7 @@ func TestFallback_TriggersOnNaturalFinish(t *testing.T) { q.SetFallbackSource(fake) q.SetQueue(seedPaths, 0, false, Source{Type: "album", ID: 1, Label: "Seed Album"}) - q.OnPlaybackFinished() + q.OnPlaybackFinished(nil) waitUntil(t, func() bool { return fake.callCount() == 1 }, "fallback to be resolved") waitUntil(t, func() bool { @@ -159,7 +159,7 @@ func TestFallback_EmptyResultLeavesQueueExhausted(t *testing.T) { q.SetFallbackSource(fake) q.SetQueue(seedPaths, 0, false, Source{}) - q.OnPlaybackFinished() + q.OnPlaybackFinished(nil) waitUntil(t, func() bool { return fake.callCount() == 1 }, "fallback to be resolved") @@ -193,7 +193,7 @@ func TestFallback_StaleResolutionDiscarded(t *testing.T) { q.SetFallbackSource(fake) q.SetQueue(seedPaths, 0, false, Source{}) - q.OnPlaybackFinished() // starts resolving, blocked on gate + q.OnPlaybackFinished(nil) // starts resolving, blocked on gate time.Sleep(20 * time.Millisecond) // let the goroutine reach the gate diff --git a/backend/queue/finished_test.go b/backend/queue/finished_test.go new file mode 100644 index 0000000..7cfcefe --- /dev/null +++ b/backend/queue/finished_test.go @@ -0,0 +1,78 @@ +package queue + +import ( + "errors" + "testing" + + "yellowjacket/backend/events" +) + +// errTestDecode stands in for a decoder blowing up mid-track. +var errTestDecode = errors.New("decode blew up") + +// currentIndex == -1 against a non-empty queue is a state this +// package produces on purpose: onQueueExhausted(false) sets it and +// deliberately leaves the finished track loaded in the player, so it +// stays on the now-playing bar. Pressing play from there and letting +// it finish re-enters OnPlaybackFinished with exactly that pair -- +// which used to index q.tracks[-1] and panic, on a goroutine +// dispatched from the audio callback with no caller to recover it. +func TestFinishedWithNoCurrentTrackDoesNotPanic(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + index int + }{ + {"exhausted queue leaves -1", -1}, + {"index past the end", 3}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + q, _, _ := setupRecordedQueue(t) + q.tracks = []Track{ + {FilePath: "/a.mp3"}, + {FilePath: "/b.mp3"}, + } + q.currentIndex = tt.index + + // The assertion is that this returns at all. + q.OnPlaybackFinished(nil) + + if q.currentIndex != tt.index { + t.Errorf( + "an out-of-range index was acted on: %d became %d", + tt.index, q.currentIndex, + ) + } + }) + } +} + +// A track that broke mid-playback is not a track that was listened +// to. The player cannot say so itself -- the metadata is here -- so +// it hands the reason over and this is where it becomes a +// PlaybackFailed rather than a silent auto-advance. +func TestAFailedTrackIsReportedAndNotCountedAsAPlay(t *testing.T) { + t.Parallel() + + q, _, rec := setupRecordedQueue(t) + q.tracks = []Track{ + {FilePath: "/a.mp3", Title: "A", AudioFileID: 1}, + {FilePath: "/b.mp3", Title: "B", AudioFileID: 2}, + } + q.currentIndex = 0 + + q.OnPlaybackFinished(errTestDecode) + + if _, ok := rec.Last(events.PlaybackFailed); !ok { + t.Errorf( + "a track that failed mid-playback told the user nothing; "+ + "got %v", + rec.Names(), + ) + } +} diff --git a/backend/queue/handlers.go b/backend/queue/handlers.go index b3d44e9..a0a9054 100644 --- a/backend/queue/handlers.go +++ b/backend/queue/handlers.go @@ -1,18 +1,45 @@ package queue -// OnPlaybackFinished is called when a track finishes playing naturally. -// This drives the auto-advance behavior and records the play. -func (q *Queue) OnPlaybackFinished() { +// OnPlaybackFinished is called when a track stops streaming. This +// drives the auto-advance behavior and records the play. +// +// srcErr says why the track stopped: nil for one that reached its +// end, non-nil for one that broke partway through. The player cannot +// tell the user which, because the metadata lives here -- so a failure +// is reported as PlaybackFailed and *not* recorded as a play, while +// the advance happens either way. Before this, a file that failed +// mid-track advanced in silence and was counted as listened to. +// +//wails:ignore // internal wiring, not part of the app's IPC surface. +func (q *Queue) OnPlaybackFinished(srcErr error) { q.mu.Lock() - if len(q.tracks) == 0 { + // currentIndex is -1 whenever the queue has been exhausted, and + // onQueueExhausted deliberately leaves the finished track loaded + // in the player -- so a natural finish can re-enter here against a + // queue that is not empty and an index that is not valid. Every + // other path in this package bounds-checks before indexing; this + // one panicked, on a goroutine with no caller to recover it. + if q.currentIndex < 0 || q.currentIndex >= len(q.tracks) { q.mu.Unlock() return } // Capture the track that just finished before advancing. - finishedID := q.tracks[q.currentIndex].AudioFileID + finished := q.tracks[q.currentIndex] + finishedID := finished.AudioFileID + + if srcErr != nil { + q.emitPlaybackFailed(finished, srcErr) + } + + // A track that broke was not listened to. + recordFinished := func() { + if srcErr == nil { + q.recordPlay(finishedID) + } + } // Repeat One: replay the current track. if q.repeatMode == RepeatOne { @@ -21,7 +48,7 @@ func (q *Queue) OnPlaybackFinished() { } q.mu.Unlock() - q.recordPlay(finishedID) + recordFinished() return } @@ -31,7 +58,7 @@ func (q *Queue) OnPlaybackFinished() { // Queue exhausted — this is the extension point for a future fallback playlist. q.onQueueExhausted(false) q.mu.Unlock() - q.recordPlay(finishedID) + recordFinished() return } @@ -44,12 +71,12 @@ func (q *Queue) OnPlaybackFinished() { if !q.playCurrentOrSkip(true, q.nextIndex) { q.onQueueExhausted(false) q.mu.Unlock() - q.recordPlay(finishedID) + recordFinished() return } q.emitIndexChanged() q.mu.Unlock() - q.recordPlay(finishedID) + recordFinished() } diff --git a/backend/queue/playbackfailed_test.go b/backend/queue/playbackfailed_test.go index 3ad8179..3c973e0 100644 --- a/backend/queue/playbackfailed_test.go +++ b/backend/queue/playbackfailed_test.go @@ -107,7 +107,7 @@ func TestPlaybackFailed_AutoAdvanceSkipsPastIt(t *testing.T) { // The first track finished: auto-advance lands on the missing // file and must step over it rather than stopping dead. - q.OnPlaybackFinished() + q.OnPlaybackFinished(nil) if got := q.GetState().CurrentIndex; got != 2 { t.Errorf("currentIndex after skipping: got %d, want 2", got) @@ -183,7 +183,7 @@ func TestQueueExhausted_KeepsTheFinishedTrackLoaded(t *testing.T) { q.SetQueue(paths, 0, false, Source{}) q.Play() - q.OnPlaybackFinished() + q.OnPlaybackFinished(nil) if q.GetState().CurrentIndex != -1 { t.Errorf( diff --git a/frontend/bindings/yellowjacket/backend/queue/queue.ts b/frontend/bindings/yellowjacket/backend/queue/queue.ts index ee9bc23..5200a95 100644 --- a/frontend/bindings/yellowjacket/backend/queue/queue.ts +++ b/frontend/bindings/yellowjacket/backend/queue/queue.ts @@ -113,14 +113,6 @@ export function Next(): $CancellablePromise { return $Call.ByID(1968784044); } -/** - * OnPlaybackFinished is called when a track finishes playing naturally. - * This drives the auto-advance behavior and records the play. - */ -export function OnPlaybackFinished(): $CancellablePromise { - return $Call.ByID(2184869763); -} - /** * Play handles a play request by either resuming the current track or * starting playback from the beginning of the queue. When a track is -- 2.54.0 From 61d549a9d5b936a58e99a95d51b8a41ed7d0b31f Mon Sep 17 00:00:00 2001 From: Caleb Allen Date: Wed, 19 Aug 2026 09:16:43 -0400 Subject: [PATCH 3/3] ci: run the pre-push hooks sequentially `go test -race ./...` saturates every core for ~47s, and the UI tier it was sharing them with is a real Chromium with wall-clock timeouts. So the browser lost, at random: setup took 106s inside the hook against 63s standalone, and a different suite failed on each run -- three failing to fetch setup.ts from Vitest's own dev server once, a 15s "did not mount itself" the next time -- against a suite that passes 898/898 five times running on its own. That reads as "your branch broke the frontend" when nothing is wrong, which is the most expensive kind of false negative: the next person bisects a change that was never at fault. It cost two pushes here before the summary line gave it away. Sequential costs about 15s. Closes #128 --- lefthook.yml | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/lefthook.yml b/lefthook.yml index eb6614c..7c56e83 100644 --- a/lefthook.yml +++ b/lefthook.yml @@ -63,8 +63,17 @@ pre-commit: root: "frontend/" run: node scripts/check-css-literals.mjs +# Deliberately sequential, unlike pre-commit. `go test -race` +# saturates every core for the better part of a minute and the UI tier +# is a real browser with wall-clock timeouts, so run together the +# browser loses: setup took 106s inside the hook against 63s +# standalone, and a different suite failed each time -- three suites +# failing to fetch setup.ts from Vitest's own dev server on one run, a +# 15s "did not mount itself" on the next, against a suite that passes +# 898/898 on its own. A gate that fails at random is not a gate. The +# ~15s saved is not worth it. pre-push: - parallel: true + parallel: false commands: go-test: glob: "*.go" -- 2.54.0