Files
Bose-SoundTouch/pkg/service/soundtouchweb/logutil_test.go
T
Tobias GesellchenandClaude Opus 4.8 040469a074 feat(web): log playback requests and now_playing error transitions
soundtouch-web had no logging on its play/select paths, which made
issues like #345 (a source rejected by the speaker) hard to diagnose:
a SoundTouch /select returns HTTP 200 even when the source is then
rejected, so the failure only surfaces asynchronously as a now_playing
transition to an error source, and nothing recorded it.

Add two log points:
- logPlaybackRequest: one line per play/select with the resolved
  source, sourceAccount, location and itemName, from all five handlers
  (source-select, device-play, play-url, radiobrowser, tunein). This is
  often the only record of what was actually requested. sourceAccount
  here is an account identifier, not a bearer credential.
- logNowPlayingError: logs when a device's now_playing enters an error
  source (INVALID_SOURCE or any *_ERROR), deduped per transition, which
  is the real signal that a selection failed on the speaker.

The two TuneIn/RadioBrowser handlers now resolve the ContentItem via
stations.ResolveContentItem and select it directly so the log shows the
authoritative outgoing source; the now-unused stations.Play wrapper is
removed.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
2026-06-02 23:00:58 +02:00

89 lines
2.0 KiB
Go

package soundtouchweb
import (
"bytes"
"log"
"strings"
"testing"
)
func TestIsErrorSource(t *testing.T) {
tests := []struct {
source string
want bool
}{
{"INVALID_SOURCE", true},
{"UNKNOWN_SOURCE_ERROR", true},
{"INTERNET_RADIO_ERROR", true},
{"STANDBY", false},
{"TUNEIN", false},
{"AUX", false},
{"", false},
}
for _, tt := range tests {
if got := isErrorSource(tt.source); got != tt.want {
t.Errorf("isErrorSource(%q) = %v, want %v", tt.source, got, tt.want)
}
}
}
// captureLog redirects the standard logger for the duration of f and returns
// what was written.
func captureLog(t *testing.T, f func()) string {
t.Helper()
var buf bytes.Buffer
prevOut := log.Writer()
prevFlags := log.Flags()
log.SetOutput(&buf)
log.SetFlags(0)
t.Cleanup(func() {
log.SetOutput(prevOut)
log.SetFlags(prevFlags)
})
f()
return buf.String()
}
func TestLogPlaybackRequest(t *testing.T) {
out := captureLog(t, func() {
logPlaybackRequest("source-select", "DEVICEID01", "AUX", "AUX1", "", "")
})
for _, want := range []string{`[play]`, `source-select`, `device="DEVICEID01"`, `source="AUX"`, `sourceAccount="AUX1"`} {
if !strings.Contains(out, want) {
t.Errorf("log output %q missing %q", out, want)
}
}
}
func TestLogPlaybackRequest_SanitizesNewlines(t *testing.T) {
out := captureLog(t, func() {
logPlaybackRequest("device-play", "DEVICEID01", "TUNEIN", "", "http://evil/\nINJECTED line", "Station")
})
if strings.Contains(out, "\nINJECTED") {
t.Errorf("log output not sanitized against newline injection: %q", out)
}
if !strings.Contains(out, `\nINJECTED`) {
t.Errorf("expected escaped newline in output, got %q", out)
}
}
func TestLogNowPlayingError(t *testing.T) {
out := captureLog(t, func() {
logNowPlayingError("DEVICEID01", "INVALID_SOURCE", "")
})
for _, want := range []string{`now_playing entered error`, `source="INVALID_SOURCE"`, `device="DEVICEID01"`} {
if !strings.Contains(out, want) {
t.Errorf("log output %q missing %q", out, want)
}
}
}