Files
Bose-SoundTouch/pkg/service/soundtouchweb/logutil.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

59 lines
2.3 KiB
Go

package soundtouchweb
import (
"log"
"strings"
)
// sanitizeLog strips newline characters from s to prevent log-injection
// (CodeQL go/log-injection). Values from speakers, HTTP requests, and
// external APIs may contain attacker-controlled newlines.
func sanitizeLog(s string) string {
s = strings.ReplaceAll(s, "\n", `\n`)
s = strings.ReplaceAll(s, "\r", `\r`)
return s
}
// logPlaybackRequest records what soundtouch-web is about to ask a speaker to
// play or switch to. A SoundTouch /select returns HTTP 200 even when the
// source is ultimately rejected: the failure only surfaces afterwards as a
// now_playing transition to an error source (see logNowPlayingError). So this
// line is frequently the only record of what was actually requested, and the
// pair (request here, error transition there) is what closes the loop when
// diagnosing source/playback failures.
//
// sourceAccount here is an account identifier (e.g. "AUX1" for a specific jack,
// or a placeholder username), not a bearer credential: the real OAuth tokens
// live in the service datastore, not in the ContentItem sent on /select. It is
// logged as-is so multi-account sources can be debugged.
func logPlaybackRequest(action, deviceID, source, sourceAccount, location, itemName string) {
log.Printf("[play] %s device=%q source=%q sourceAccount=%q location=%q itemName=%q",
sanitizeLog(action),
sanitizeLog(deviceID),
sanitizeLog(source),
sanitizeLog(sourceAccount),
sanitizeLog(location),
sanitizeLog(itemName),
)
}
// isErrorSource reports whether a now_playing source value indicates the
// speaker rejected or failed a selection rather than entering a normal state.
// It covers INVALID_SOURCE and the family of *_ERROR sources the firmware
// emits (e.g. UNKNOWN_SOURCE_ERROR).
func isErrorSource(source string) bool {
return source == "INVALID_SOURCE" || strings.HasSuffix(source, "_ERROR")
}
// logNowPlayingError logs when a speaker's now_playing enters an error source.
// Because /select returns 200 regardless, this asynchronous transition is the
// real signal that a selection failed on the device.
func logNowPlayingError(deviceID, source, sourceAccount string) {
log.Printf("[play] device=%q now_playing entered error source=%q sourceAccount=%q",
sanitizeLog(deviceID),
sanitizeLog(source),
sanitizeLog(sourceAccount),
)
}