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 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 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"