Some cleanup in the jukebox code, specially log messages

This commit is contained in:
Deluan 2023-12-17 13:14:34 -05:00
parent 932152eb7e
commit 12aae5e951
4 changed files with 78 additions and 71 deletions

View File

@ -2,6 +2,7 @@ package playback
import (
"context"
"errors"
"fmt"
"github.com/navidrome/navidrome/core/playback/mpv"
@ -17,9 +18,10 @@ type Track interface {
Position() int
SetPosition(offset int) error
Close()
String() string
}
type PlaybackDevice struct {
type playbackDevice struct {
ParentPlaybackServer PlaybackServer
Default bool
User string
@ -43,7 +45,7 @@ const DefaultGain float32 = 1.0
var EmptyStatus = DeviceStatus{CurrentIndex: -1, Playing: false, Gain: DefaultGain, Position: 0}
func (pd *PlaybackDevice) getStatus() DeviceStatus {
func (pd *playbackDevice) getStatus() DeviceStatus {
pos := 0
if pd.ActiveTrack != nil {
pos = pd.ActiveTrack.Position()
@ -59,8 +61,8 @@ func (pd *PlaybackDevice) getStatus() DeviceStatus {
// NewPlaybackDevice creates a new playback device which implements all the basic Jukebox mode commands defined here:
// http://www.subsonic.org/pages/api.jsp#jukeboxControl
// Starts the trackSwitcher goroutine for the device.
func NewPlaybackDevice(playbackServer PlaybackServer, name string, deviceName string) *PlaybackDevice {
return &PlaybackDevice{
func NewPlaybackDevice(playbackServer PlaybackServer, name string, deviceName string) *playbackDevice {
return &playbackDevice{
ParentPlaybackServer: playbackServer,
User: "",
Name: name,
@ -72,22 +74,24 @@ func NewPlaybackDevice(playbackServer PlaybackServer, name string, deviceName st
}
}
func (pd *PlaybackDevice) String() string {
func (pd *playbackDevice) String() string {
return fmt.Sprintf("Name: %s, Gain: %.4f, Loaded track: %s", pd.Name, pd.Gain, pd.ActiveTrack)
}
func (pd *PlaybackDevice) Get(ctx context.Context) (model.MediaFiles, DeviceStatus, error) {
log.Debug(ctx, "processing Get action")
func (pd *playbackDevice) Get(ctx context.Context) (model.MediaFiles, DeviceStatus, error) {
log.Debug(ctx, "Processing Get action", "device", pd)
return pd.PlaybackQueue.Get(), pd.getStatus(), nil
}
func (pd *PlaybackDevice) Status(ctx context.Context) (DeviceStatus, error) {
func (pd *playbackDevice) Status(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, fmt.Sprintf("processing Status action on: %s, queue: %s", pd, pd.PlaybackQueue))
return pd.getStatus(), nil
}
// set is similar to a clear followed by a add, but will not change the currently playing track.
func (pd *PlaybackDevice) Set(ctx context.Context, ids []string) (DeviceStatus, error) {
// Set is similar to a clear followed by a add, but will not change the currently playing track.
func (pd *playbackDevice) Set(ctx context.Context, ids []string) (DeviceStatus, error) {
log.Debug(ctx, "Processing Set action", "ids", ids, "device", pd)
_, err := pd.Clear(ctx)
if err != nil {
log.Error(ctx, "error setting tracks", ids)
@ -96,8 +100,8 @@ func (pd *PlaybackDevice) Set(ctx context.Context, ids []string) (DeviceStatus,
return pd.Add(ctx, ids)
}
func (pd *PlaybackDevice) Start(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "processing Start action")
func (pd *playbackDevice) Start(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "Processing Start action", "device", pd)
if !pd.TrackSwitcherStarted {
log.Info(ctx, "Starting trackSwitcher goroutine")
@ -127,16 +131,16 @@ func (pd *PlaybackDevice) Start(ctx context.Context) (DeviceStatus, error) {
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) Stop(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "processing Stop action")
func (pd *playbackDevice) Stop(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "Processing Stop action", "device", pd)
if pd.ActiveTrack != nil {
pd.ActiveTrack.Pause()
}
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) Skip(ctx context.Context, index int, offset int) (DeviceStatus, error) {
log.Debug(ctx, "processing Skip action", "index", index, "offset", offset)
func (pd *playbackDevice) Skip(ctx context.Context, index int, offset int) (DeviceStatus, error) {
log.Debug(ctx, "Processing Skip action", "index", index, "offset", offset, "device", pd)
wasPlaying := pd.isPlaying()
@ -173,8 +177,11 @@ func (pd *PlaybackDevice) Skip(ctx context.Context, index int, offset int) (Devi
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) Add(ctx context.Context, ids []string) (DeviceStatus, error) {
log.Debug(ctx, "processing Add action")
func (pd *playbackDevice) Add(ctx context.Context, ids []string) (DeviceStatus, error) {
log.Debug(ctx, "Processing Add action", "ids", ids, "device", pd)
if len(ids) < 1 {
return pd.getStatus(), nil
}
items := model.MediaFiles{}
@ -191,8 +198,8 @@ func (pd *PlaybackDevice) Add(ctx context.Context, ids []string) (DeviceStatus,
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) Clear(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, fmt.Sprintf("processing Clear action on: %s", pd))
func (pd *playbackDevice) Clear(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "Processing Clear action", "device", pd)
if pd.ActiveTrack != nil {
pd.ActiveTrack.Pause()
pd.ActiveTrack.Close()
@ -202,8 +209,8 @@ func (pd *PlaybackDevice) Clear(ctx context.Context) (DeviceStatus, error) {
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) Remove(ctx context.Context, index int) (DeviceStatus, error) {
log.Debug(ctx, "processing Remove action")
func (pd *playbackDevice) Remove(ctx context.Context, index int) (DeviceStatus, error) {
log.Debug(ctx, "Processing Remove action", "index", index, "device", pd)
// pausing if attempting to remove running track
if pd.isPlaying() && pd.PlaybackQueue.Index == index {
_, err := pd.Stop(ctx)
@ -221,17 +228,17 @@ func (pd *PlaybackDevice) Remove(ctx context.Context, index int) (DeviceStatus,
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) Shuffle(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "processing Shuffle action")
func (pd *playbackDevice) Shuffle(ctx context.Context) (DeviceStatus, error) {
log.Debug(ctx, "Processing Shuffle action", "device", pd)
if pd.PlaybackQueue.Size() > 1 {
pd.PlaybackQueue.Shuffle()
}
return pd.getStatus(), nil
}
// Used to control the playback volume. A float value between 0.0 and 1.0.
func (pd *PlaybackDevice) SetGain(ctx context.Context, gain float32) (DeviceStatus, error) {
log.Debug(ctx, fmt.Sprintf("processing SetGain action. Actual gain: %f, gain to set: %f", pd.Gain, gain))
// SetGain is used to control the playback volume. A float value between 0.0 and 1.0.
func (pd *playbackDevice) SetGain(ctx context.Context, gain float32) (DeviceStatus, error) {
log.Debug(ctx, "Processing SetGain action", "newGain", gain, "device", pd)
if pd.ActiveTrack != nil {
pd.ActiveTrack.SetVolume(gain)
@ -241,15 +248,15 @@ func (pd *PlaybackDevice) SetGain(ctx context.Context, gain float32) (DeviceStat
return pd.getStatus(), nil
}
func (pd *PlaybackDevice) isPlaying() bool {
func (pd *playbackDevice) isPlaying() bool {
return pd.ActiveTrack != nil && pd.ActiveTrack.IsPlaying()
}
func (pd *PlaybackDevice) trackSwitcherGoroutine() {
log.Info("Starting trackSwitcher goroutine")
func (pd *playbackDevice) trackSwitcherGoroutine() {
log.Debug("Started trackSwitcher goroutine", "device", pd)
for {
<-pd.PlaybackDone
log.Info("track switching detected")
log.Debug("Track switching detected")
if pd.ActiveTrack != nil {
pd.ActiveTrack.Close()
pd.ActiveTrack = nil
@ -260,7 +267,7 @@ func (pd *PlaybackDevice) trackSwitcherGoroutine() {
log.Debug("Switching to next song", "queue", pd.PlaybackQueue.String())
err := pd.switchActiveTrackByIndex(pd.PlaybackQueue.Index)
if err != nil {
log.Error("error switching track", "error", err)
log.Error("Error switching track", err)
}
pd.ActiveTrack.Unpause()
} else {
@ -269,11 +276,11 @@ func (pd *PlaybackDevice) trackSwitcherGoroutine() {
}
}
func (pd *PlaybackDevice) switchActiveTrackByIndex(index int) error {
func (pd *playbackDevice) switchActiveTrackByIndex(index int) error {
pd.PlaybackQueue.SetIndex(index)
currentTrack := pd.PlaybackQueue.Current()
if currentTrack == nil {
return fmt.Errorf("could not get current track")
return errors.New("could not get current track")
}
track, err := mpv.NewTrack(pd.PlaybackDone, pd.DeviceName, *currentTrack)

View File

@ -25,7 +25,7 @@ type MpvTrack struct {
}
func NewTrack(playbackDoneChannel chan bool, deviceName string, mf model.MediaFile) (*MpvTrack, error) {
log.Debug("loading track", "trackname", mf.Path, "mediatype", mf.ContentType())
log.Debug("Loading track", "trackPath", mf.Path, "mediaType", mf.ContentType())
if _, err := mpvCommand(); err != nil {
return nil, err
@ -36,14 +36,14 @@ func NewTrack(playbackDoneChannel chan bool, deviceName string, mf model.MediaFi
args := createMPVCommand(mpvComdTemplate, deviceName, mf.Path, tmpSocketName)
exe, err := start(args)
if err != nil {
log.Error("error starting mpv process", "error", err)
log.Error("Error starting mpv process", err)
return nil, err
}
// wait for socket to show up
err = waitForFile(tmpSocketName, 3*time.Second, 100*time.Millisecond)
err = waitForSocket(tmpSocketName, 3*time.Second, 100*time.Millisecond)
if err != nil {
log.Error("error or timeout waiting for control socket", "socketname", tmpSocketName, "error", err)
log.Error("Error or timeout waiting for control socket", "socketname", tmpSocketName, err)
return nil, err
}
@ -51,7 +51,7 @@ func NewTrack(playbackDoneChannel chan bool, deviceName string, mf model.MediaFi
err = conn.Open()
if err != nil {
log.Error("error opening new connection", "error", err)
log.Error("Error opening new connection", err)
return nil, err
}
@ -92,7 +92,7 @@ func (t *MpvTrack) Unpause() {
if err != nil {
log.Error(err)
}
log.Info("unpaused track")
log.Debug("Unpaused track", "track", t)
}
func (t *MpvTrack) Pause() {
@ -111,7 +111,7 @@ func (t *MpvTrack) Close() {
log.Debug("sending shutdown command")
_, err := t.Conn.Call("quit")
if err != nil {
log.Error("error sending quit command to mpv-ipc socket", "error", err)
log.Error("Error sending quit command to mpv-ipc socket", err)
if t.Exe != nil {
log.Debug("cancelling executor")
@ -141,16 +141,16 @@ func (t *MpvTrack) isSocketfilePresent() bool {
return err == nil && fileInfo != nil && !fileInfo.IsDir()
}
// Position returns the playback position in seconds
// every now and then the mpv IPC interface returns "mpv error: property unavailable"
// Position returns the playback position in seconds.
// Every now and then the mpv IPC interface returns "mpv error: property unavailable"
// in this case we have to retry
func (t *MpvTrack) Position() int {
retryCount := 0
for {
position, err := t.Conn.Get("time-pos")
if err != nil && err.Error() == "mpv error: property unavailable" {
log.Debug("got the mpv error: property unavailable error, retry ...")
retryCount += 1
log.Debug("Got mpv error, retrying...", "retries", retryCount, err)
if retryCount > 5 {
return 0
}
@ -158,13 +158,13 @@ func (t *MpvTrack) Position() int {
}
if err != nil {
log.Error("error getting position in track", "error", err)
log.Error("Error getting position in track", err)
return 0
}
pos, ok := position.(float64)
if !ok {
log.Error("could not cast position from mpv into float64")
log.Error("Could not cast position from mpv into float64", "position", position)
return 0
} else {
return int(pos)
@ -181,7 +181,7 @@ func (t *MpvTrack) SetPosition(offset int) error {
}
err := t.Conn.Set("time-pos", float64(offset))
if err != nil {
log.Error("could not set the position in track", "offset", offset, "error", err)
log.Error("could not set the position in track", "offset", offset, err)
return err
}
log.Info("set position", "offset", offset)
@ -191,7 +191,7 @@ func (t *MpvTrack) SetPosition(offset int) error {
func (t *MpvTrack) IsPlaying() bool {
pausing, err := t.Conn.Get("pause")
if err != nil {
log.Error("problem getting paused status", "error", err)
log.Error("problem getting paused status", err)
return false
}
@ -203,7 +203,7 @@ func (t *MpvTrack) IsPlaying() bool {
return !pause
}
func waitForFile(path string, timeout time.Duration, pause time.Duration) error {
func waitForSocket(path string, timeout time.Duration, pause time.Duration) error {
start := time.Now()
end := start.Add(timeout)
var retries int = 0
@ -211,7 +211,7 @@ func waitForFile(path string, timeout time.Duration, pause time.Duration) error
for {
fileInfo, err := os.Stat(path)
if err == nil && fileInfo != nil && !fileInfo.IsDir() {
log.Debug("file found", "retries", retries, "waittime", time.Since(start).Microseconds())
log.Debug("Socket found", "retries", retries, "waitTime", time.Since(start))
return nil
}
if time.Now().After(end) {

View File

@ -19,7 +19,7 @@ import (
type PlaybackServer interface {
Run(ctx context.Context) error
GetDeviceForUser(user string) (*PlaybackDevice, error)
GetDeviceForUser(user string) (*playbackDevice, error)
GetMediaFile(id string) (*model.MediaFile, error)
GetCtx() *context.Context
}
@ -27,7 +27,7 @@ type PlaybackServer interface {
type playbackServer struct {
ctx *context.Context
datastore model.DataStore
playbackDevices []PlaybackDevice
playbackDevices []playbackDevice
}
// GetInstance returns the playback-server singleton
@ -63,8 +63,8 @@ func (ps *playbackServer) GetCtx() *context.Context {
return ps.ctx
}
func (ps *playbackServer) initDeviceStatus(devices []conf.AudioDeviceDefinition, defaultDevice string) ([]PlaybackDevice, error) {
pbDevices := make([]PlaybackDevice, max(1, len(devices)))
func (ps *playbackServer) initDeviceStatus(devices []conf.AudioDeviceDefinition, defaultDevice string) ([]playbackDevice, error) {
pbDevices := make([]playbackDevice, max(1, len(devices)))
defaultDeviceFound := false
if defaultDevice == "" {
@ -76,13 +76,13 @@ func (ps *playbackServer) initDeviceStatus(devices []conf.AudioDeviceDefinition,
// if there is but only one entry and no default given, just use that.
if len(devices) == 1 {
if len(devices[0]) != 2 {
return []PlaybackDevice{}, fmt.Errorf("audio device definition ought to contain 2 fields, found: %d ", len(devices[0]))
return []playbackDevice{}, fmt.Errorf("audio device definition ought to contain 2 fields, found: %d ", len(devices[0]))
}
pbDevices[0] = *NewPlaybackDevice(ps, devices[0][0], devices[0][1])
}
if len(devices) > 1 {
return []PlaybackDevice{}, fmt.Errorf("number of audio device found is %d, but no default device defined. Set Jukebox.Default", len(devices))
return []playbackDevice{}, fmt.Errorf("number of audio device found is %d, but no default device defined. Set Jukebox.Default", len(devices))
}
pbDevices[0].Default = true
@ -91,7 +91,7 @@ func (ps *playbackServer) initDeviceStatus(devices []conf.AudioDeviceDefinition,
for idx, audioDevice := range devices {
if len(audioDevice) != 2 {
return []PlaybackDevice{}, fmt.Errorf("audio device definition ought to contain 2 fields, found: %d ", len(audioDevice))
return []playbackDevice{}, fmt.Errorf("audio device definition ought to contain 2 fields, found: %d ", len(audioDevice))
}
pbDevices[idx] = *NewPlaybackDevice(ps, audioDevice[0], audioDevice[1])
@ -103,18 +103,18 @@ func (ps *playbackServer) initDeviceStatus(devices []conf.AudioDeviceDefinition,
}
if !defaultDeviceFound {
return []PlaybackDevice{}, fmt.Errorf("default device name not found: %s ", defaultDevice)
return []playbackDevice{}, fmt.Errorf("default device name not found: %s ", defaultDevice)
}
return pbDevices, nil
}
func (ps *playbackServer) getDefaultDevice() (*PlaybackDevice, error) {
func (ps *playbackServer) getDefaultDevice() (*playbackDevice, error) {
for idx, audioDevice := range ps.playbackDevices {
if audioDevice.Default {
return &ps.playbackDevices[idx], nil
}
}
return &PlaybackDevice{}, fmt.Errorf("no default device found")
return &playbackDevice{}, fmt.Errorf("no default device found")
}
// GetMediaFile retrieves the MediaFile given by the id parameter
@ -123,12 +123,12 @@ func (ps *playbackServer) GetMediaFile(id string) (*model.MediaFile, error) {
}
// GetDeviceForUser returns the audio playback device for the given user. As of now this is but only the default device.
func (ps *playbackServer) GetDeviceForUser(user string) (*PlaybackDevice, error) {
log.Debug("processing GetDevice")
func (ps *playbackServer) GetDeviceForUser(user string) (*playbackDevice, error) {
log.Debug("Processing GetDevice", "user", user)
// README: here we might plug-in the user-device mapping one fine day
device, err := ps.getDefaultDevice()
if err != nil {
return &PlaybackDevice{}, err
return &playbackDevice{}, err
}
device.User = user
return device, nil

View File

@ -64,13 +64,13 @@ func (api *Router) getAlbumList(r *http.Request) (model.Albums, int64, error) {
albums, err := api.ds.Album(r.Context()).GetAllWithoutGenres(opts)
if err != nil {
log.Error(r, "Error retrieving albums", "error", err)
log.Error(r, "Error retrieving albums", err)
return nil, 0, newError(responses.ErrorGeneric, "internal error")
}
count, err := api.ds.Album(r.Context()).CountAll(opts)
if err != nil {
log.Error(r, "Error counting albums", "error", err)
log.Error(r, "Error counting albums", err)
return nil, 0, newError(responses.ErrorGeneric, "internal error")
}
@ -108,17 +108,17 @@ func (api *Router) GetStarred(r *http.Request) (*responses.Subsonic, error) {
options := filter.Starred()
artists, err := api.ds.Artist(ctx).GetAll(options)
if err != nil {
log.Error(r, "Error retrieving starred artists", "error", err)
log.Error(r, "Error retrieving starred artists", err)
return nil, err
}
albums, err := api.ds.Album(ctx).GetAllWithoutGenres(options)
if err != nil {
log.Error(r, "Error retrieving starred albums", "error", err)
log.Error(r, "Error retrieving starred albums", err)
return nil, err
}
mediaFiles, err := api.ds.MediaFile(ctx).GetAll(options)
if err != nil {
log.Error(r, "Error retrieving starred mediaFiles", "error", err)
log.Error(r, "Error retrieving starred mediaFiles", err)
return nil, err
}
@ -145,7 +145,7 @@ func (api *Router) GetNowPlaying(r *http.Request) (*responses.Subsonic, error) {
ctx := r.Context()
npInfo, err := api.scrobbler.GetNowPlaying(ctx)
if err != nil {
log.Error(r, "Error retrieving now playing list", "error", err)
log.Error(r, "Error retrieving now playing list", err)
return nil, err
}
@ -170,7 +170,7 @@ func (api *Router) GetRandomSongs(r *http.Request) (*responses.Subsonic, error)
songs, err := api.getSongs(r.Context(), 0, size, filter.SongsByRandom(genre, fromYear, toYear))
if err != nil {
log.Error(r, "Error retrieving random songs", "error", err)
log.Error(r, "Error retrieving random songs", err)
return nil, err
}
@ -187,7 +187,7 @@ func (api *Router) GetSongsByGenre(r *http.Request) (*responses.Subsonic, error)
songs, err := api.getSongs(r.Context(), offset, count, filter.SongsByGenre(genre))
if err != nil {
log.Error(r, "Error retrieving random songs", "error", err)
log.Error(r, "Error retrieving random songs", err)
return nil, err
}