fix(soundtouchweb): auto-resume playback after an unsolicited SOURCE_DISCONNECTED (#622)

A speaker can drop its own active source mid-playback (errorUpdate 1041 SOURCE_DISCONNECTED -> now_playing INVALID_SOURCE) while the SoundTouch WebSocket control channel stays healthy throughout. Nothing previously noticed this: logNowPlayingError only logged the transition, leaving the speaker silent until someone manually re-selected the source. Add autoResumeState, tracking the last healthy ContentItem per device connection. On a fresh transition into an error source (not a repeat of one already seen), it re-issues that ContentItem via SelectContentItem after a short backoff - the same call pressing the preset again makes. No attempt cap: if the resume itself fails, the source stays in error and nothing fires again until a genuine recovery is observed, which already bounds retries for a station that's truly gone without capping a station that legitimately (and repeatedly) recovers on its own.
2026-08-18 08:36:13 +00:00 · 2026-08-17 21:57:22 +02:00
parent e57708ea11
commit df7b0fc7ae
3 changed files with 298 additions and 0 deletions
@@ -0,0 +1,98 @@
+package soundtouchweb
+
+import (
+	"log"
+	"time"
+
+	"github.com/gesellix/bose-soundtouch/pkg/models"
+	"github.com/gesellix/bose-soundtouch/pkg/service/soundtouchweb/webtypes"
+)
+
+// autoResumeBackoff is the delay before re-issuing a dropped content item,
+// giving a transient upstream hiccup a moment to clear before retrying.
+const autoResumeBackoff = 2 * time.Second
+
+// autoResumeState tracks what ConnectDeviceWebSocket needs to decide whether
+// a now_playing transition should trigger an auto-resume. Split out from the
+// WebSocket goroutine so the decision can be unit tested without a live
+// connection.
+//
+// resumeAttempts only labels log lines — it is never used to cap retries.
+// A resume is gated on wasError being false (see observe), which already
+// means at most one attempt ever fires per drop: if the attempt fails and
+// the source stays in error, every following event has wasError=true and
+// nothing fires again until a genuine recovery is observed. A station that
+// keeps recovering and re-dropping (the reported #622 pattern — a TuneIn
+// stream disconnecting the speaker on a fixed cycle, indefinitely, while
+// otherwise healthy) is exactly the case this should keep resuming forever.
+type autoResumeState struct {
+	lastGoodContentItem *models.ContentItem
+	resumeAttempts      int
+}
+
+// observe updates the state for a new now_playing event and reports whether
+// the caller should fire an auto-resume for item, plus a label for the log
+// line. prevSource is the source seen on the previous event.
+//
+// #622: some TuneIn stations disconnect the speaker's audio pipeline on
+// their own (errorUpdate 1041 SOURCE_DISCONNECTED, observed ~5m35s into
+// playback on one reporter's setup) even though the SoundTouch WebSocket
+// control channel stays healthy throughout. The firmware does not recover
+// on its own, so a fresh transition into an error source right after a
+// healthy one — the speaker dropping a source it didn't choose to leave, as
+// opposed to the user picking a new one — re-issues the last content item,
+// exactly what pressing the physical preset button again does.
+func (s *autoResumeState) observe(prevSource string, np *models.NowPlaying) (item *models.ContentItem, attempt int, shouldResume bool) {
+	wasError := isErrorSource(prevSource)
+	nowError := isErrorSource(np.Source)
+
+	if !nowError {
+		if np.ContentItem != nil {
+			s.lastGoodContentItem = np.ContentItem
+		}
+
+		return nil, 0, false
+	}
+
+	if wasError || s.lastGoodContentItem == nil {
+		return nil, 0, false
+	}
+
+	s.resumeAttempts++
+
+	return s.lastGoodContentItem, s.resumeAttempts, true
+}
+
+// autoResumePlayback re-selects item on conn's device after autoResumeBackoff.
+// It runs in its own goroutine (never on the WebSocket read loop) so a slow
+// or hanging /select call can't stall processing of further device events.
+func autoResumePlayback(conn *webtypes.DeviceConnection, deviceID string, item *models.ContentItem, attempt int) {
+	autoResumePlaybackAfter(conn, deviceID, item, attempt, autoResumeBackoff)
+}
+
+// autoResumePlaybackAfter is autoResumePlayback with an injectable delay so
+// tests don't have to wait out the real backoff.
+func autoResumePlaybackAfter(conn *webtypes.DeviceConnection, deviceID string, item *models.ContentItem, attempt int, delay time.Duration) {
+	timer := time.NewTimer(delay)
+	defer timer.Stop()
+
+	select {
+	case <-timer.C:
+	case <-conn.Done():
+		return
+	}
+
+	if conn.Client == nil {
+		return
+	}
+
+	if err := conn.Client.SelectContentItem(item); err != nil {
+		log.Printf("[play] device=%q auto-resume attempt %d failed: %v",
+			sanitizeLog(deviceID), attempt, err)
+
+		return
+	}
+
+	log.Printf("[play] device=%q auto-resume attempt %d re-selected source=%q location=%q",
+		sanitizeLog(deviceID), attempt, sanitizeLog(item.Source), sanitizeLog(item.Location))
+}
@@ -0,0 +1,190 @@
+package soundtouchweb
+
+import (
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/gesellix/bose-soundtouch/pkg/client"
+	"github.com/gesellix/bose-soundtouch/pkg/models"
+	"github.com/gesellix/bose-soundtouch/pkg/service/soundtouchweb/webtypes"
+)
+
+func tuneInNowPlaying(source string) *models.NowPlaying {
+	return &models.NowPlaying{
+		Source: source,
+		ContentItem: &models.ContentItem{
+			Source:   "TUNEIN",
+			Type:     "stationurl",
+			Location: "/v1/playback/station/s119025",
+			ItemName: "Arabella Lovesongs",
+		},
+	}
+}
+
+func TestAutoResumeState_HealthyRemembersContentItemAndDoesNotResume(t *testing.T) {
+	s := &autoResumeState{}
+
+	item, attempt, shouldResume := s.observe("", tuneInNowPlaying("TUNEIN"))
+	if shouldResume {
+		t.Fatalf("shouldResume = true on a healthy source, want false")
+	}
+
+	if item != nil || attempt != 0 {
+		t.Errorf("item/attempt = %v/%d, want nil/0", item, attempt)
+	}
+
+	if s.lastGoodContentItem == nil {
+		t.Fatal("lastGoodContentItem was not recorded from a healthy now_playing")
+	}
+}
+
+func TestAutoResumeState_FreshErrorAfterHealthyTriggersResume(t *testing.T) {
+	s := &autoResumeState{}
+
+	// Prime with a healthy TUNEIN event, matching the WS handler calling
+	// observe once per event with the source seen on the previous call.
+	s.observe("", tuneInNowPlaying("TUNEIN"))
+
+	item, attempt, shouldResume := s.observe("TUNEIN", tuneInNowPlaying("INVALID_SOURCE"))
+	if !shouldResume {
+		t.Fatal("shouldResume = false on a fresh error transition, want true")
+	}
+
+	if attempt != 1 {
+		t.Errorf("attempt = %d, want 1", attempt)
+	}
+
+	if item == nil || item.Location != "/v1/playback/station/s119025" {
+		t.Errorf("item = %+v, want the last healthy ContentItem", item)
+	}
+}
+
+func TestAutoResumeState_DoesNotResumeWithoutAPriorGoodContentItem(t *testing.T) {
+	s := &autoResumeState{}
+
+	// No healthy event was ever observed, so there's nothing to restore.
+	_, _, shouldResume := s.observe("", tuneInNowPlaying("INVALID_SOURCE"))
+	if shouldResume {
+		t.Fatal("shouldResume = true with no prior good ContentItem, want false")
+	}
+}
+
+func TestAutoResumeState_DoesNotResumeOnRepeatedErrorEvents(t *testing.T) {
+	s := &autoResumeState{}
+
+	s.observe("", tuneInNowPlaying("TUNEIN"))
+	s.observe("TUNEIN", tuneInNowPlaying("INVALID_SOURCE")) // first resume, attempt 1
+
+	// A second consecutive error event (wasError=true this time) must not
+	// fire another resume — one attempt per drop, not per event.
+	_, _, shouldResume := s.observe("INVALID_SOURCE", tuneInNowPlaying("INVALID_SOURCE"))
+	if shouldResume {
+		t.Fatal("shouldResume = true on a repeated error event, want false")
+	}
+}
+
+func TestAutoResumeState_KeepsResumingIndefinitelyAcrossRepeatedDrops(t *testing.T) {
+	s := &autoResumeState{}
+
+	s.observe("", tuneInNowPlaying("TUNEIN"))
+
+	// The reported #622 pattern: the same station drops and (once resumed)
+	// recovers repeatedly, indefinitely, on a fixed cycle. Each fresh drop
+	// after a genuine recovery must keep resuming — there is no cap.
+	const cycles = 20
+
+	for i := 1; i <= cycles; i++ {
+		_, attempt, shouldResume := s.observe("TUNEIN", tuneInNowPlaying("INVALID_SOURCE"))
+		if !shouldResume {
+			t.Fatalf("cycle %d: shouldResume = false, want true", i)
+		}
+
+		if attempt != i {
+			t.Errorf("cycle %d: attempt label = %d, want %d", i, attempt, i)
+		}
+
+		s.observe("INVALID_SOURCE", tuneInNowPlaying("TUNEIN")) // the resume worked
+	}
+}
+
+func TestAutoResumeState_StopsRetryingAfterAFailedResume(t *testing.T) {
+	s := &autoResumeState{}
+
+	s.observe("", tuneInNowPlaying("TUNEIN"))
+
+	_, _, shouldResume := s.observe("TUNEIN", tuneInNowPlaying("INVALID_SOURCE"))
+	if !shouldResume {
+		t.Fatal("shouldResume = false on the first drop, want true")
+	}
+
+	// The resume attempt itself failed (or the station is genuinely gone):
+	// the speaker keeps reporting the same error source on further events.
+	// wasError is now true, so nothing should fire again without a genuine
+	// recovery in between — this is what keeps a truly dead station from
+	// being retried forever.
+	for i := 0; i < 5; i++ {
+		_, _, shouldResume := s.observe("INVALID_SOURCE", tuneInNowPlaying("INVALID_SOURCE"))
+		if shouldResume {
+			t.Fatalf("iteration %d: shouldResume = true on a persisting error, want false", i)
+		}
+	}
+}
+
+func TestAutoResumePlaybackAfter_ReselectsContentItem(t *testing.T) {
+	speaker, captured := setupSpeakerMock(t, nil)
+	defer speaker.Close()
+
+	c := client.NewClient(&client.Config{Host: speaker.URL})
+	conn := webtypes.NewDeviceConnection(c, &models.DeviceInfo{DeviceID: "DEVICEID01"})
+
+	item := &models.ContentItem{Source: "TUNEIN", Type: "stationurl", Location: "/v1/playback/station/s119025", ItemName: "Arabella Lovesongs"}
+
+	done := make(chan struct{})
+	go func() {
+		autoResumePlaybackAfter(conn, "DEVICEID01", item, 1, 0)
+		close(done)
+	}()
+
+	select {
+	case <-done:
+	case <-time.After(2 * time.Second):
+		t.Fatal("autoResumePlaybackAfter did not return in time")
+	}
+
+	body, ok := captured["/select"]
+	if !ok {
+		t.Fatalf("no /select request captured; requests: %v", captured)
+	}
+
+	if !strings.Contains(body, `source="TUNEIN"`) || !strings.Contains(body, "/v1/playback/station/s119025") {
+		t.Errorf("/select body = %q, want it to carry the TUNEIN content item", body)
+	}
+}
+
+func TestAutoResumePlaybackAfter_StopsWhenConnectionClosed(t *testing.T) {
+	speaker, captured := setupSpeakerMock(t, nil)
+	defer speaker.Close()
+
+	c := client.NewClient(&client.Config{Host: speaker.URL})
+	conn := webtypes.NewDeviceConnection(c, &models.DeviceInfo{DeviceID: "DEVICEID01"})
+	conn.Close()
+
+	item := &models.ContentItem{Source: "TUNEIN", Type: "stationurl", Location: "/v1/playback/station/s119025"}
+
+	done := make(chan struct{})
+	go func() {
+		autoResumePlaybackAfter(conn, "DEVICEID01", item, 1, time.Hour)
+		close(done)
+	}()
+
+	select {
+	case <-done:
+	case <-time.After(2 * time.Second):
+		t.Fatal("autoResumePlaybackAfter did not return promptly after conn.Close()")
+	}
+
+	if _, ok := captured["/select"]; ok {
+		t.Error("/select was called after the connection was closed, want no request")
+	}
+}
@@ -166,6 +166,12 @@ func (app *WebApp) ConnectDeviceWebSocket(deviceID string, conn *webtypes.Device
 	// error source is logged once per transition into it, not on every event.
 	var prevSource string

+	// resumeState survives both the speaker's own WebSocket reconnects and
+	// this loop's outer reconnects (declared once, outside the loop) so an
+	// auto-resume can fire regardless of which layer last re-established
+	// the connection.
+	resumeState := &autoResumeState{}
+
 	for {
 		// Stop if the device was removed from the registry (conn.Close()).
 		select {
@@ -189,6 +195,10 @@ func (app *WebApp) ConnectDeviceWebSocket(deviceID string, conn *webtypes.Device
 				logNowPlayingError(deviceID, np.Source, np.SourceAccount)
 			}

+			if item, attempt, shouldResume := resumeState.observe(prevSource, np); shouldResume {
+				go autoResumePlayback(conn, deviceID, item, attempt)
+			}
+
 			prevSource = np.Source

 			conn.UpdateStatus(func(s *webtypes.DeviceStatus) {