feat: consolidate logging

Author: devgianlu

ap/ap.go

@@ -31,6 +31,8 @@ import (
 const pongAckInterval = 120 * time.Second
 
 type Accesspoint struct {
+	log *log.Entry
+
 	addr librespot.GetAddressFunc
 
 	nonce    []byte
@@ -57,8 +59,8 @@ type Accesspoint struct {
 	welcome *pb.APWelcome
 }
 
-func NewAccesspoint(addr librespot.GetAddressFunc, deviceId string) *Accesspoint {
-	return &Accesspoint{addr: addr, deviceId: deviceId, recvChans: make(map[PacketType][]chan Packet)}
+func NewAccesspoint(log *log.Entry, addr librespot.GetAddressFunc, deviceId string) *Accesspoint {
+	return &Accesspoint{log: log, addr: addr, deviceId: deviceId, recvChans: make(map[PacketType][]chan Packet)}
 }
 
 func (ap *Accesspoint) init(ctx context.Context) (err error) {
@@ -85,14 +87,14 @@ func (ap *Accesspoint) init(ctx context.Context) (err error) {
 			// we assign to ap.conn after because if Dial fails we'll have a nil ap.conn which we don't want
 			ap.conn = conn
 			// Successfully connected.
-			log.Debugf("connected to %s", addr)
+			ap.log.Debugf("connected to %s", addr)
 			return nil
 		} else if attempts >= 6 {
 			// Only try a few times before giving up.
 			return fmt.Errorf("failed to connect to AP %v: %w", addr, err)
 		}
 		// Try again with a different AP.
-		log.WithError(err).Warnf("failed to connect to AP %v, retrying with a different AP", addr)
+		ap.log.WithError(err).Warnf("failed to connect to AP %v, retrying with a different AP", addr)
 	}
 }
 
@@ -249,7 +251,7 @@ func (ap *Accesspoint) Receive(types ...PacketType) <-chan Packet {
 
 func (ap *Accesspoint) startReceiving() {
 	ap.recvLoopOnce.Do(func() {
-		log.Tracef("starting accesspoint recv loop")
+		ap.log.Tracef("starting accesspoint recv loop")
 		go ap.recvLoop()
 
 		// set last ping in the future
@@ -268,19 +270,22 @@ loop:
 			// no need to hold the connMu since reconnection happens in this routine
 			pkt, payload, err := ap.encConn.receivePacket(context.TODO())
 			if err != nil {
-				log.WithError(err).Errorf("failed receiving packet")
+				if !ap.stop {
+					ap.log.WithError(err).Errorf("failed receiving packet")
+				}
+
 				break loop
 			}
 
 			switch pkt {
 			case PacketTypePing:
-				log.Tracef("received accesspoint ping")
+				ap.log.Tracef("received accesspoint ping")
 				if err := ap.encConn.sendPacket(context.TODO(), PacketTypePong, payload); err != nil {
-					log.WithError(err).Errorf("failed sending Pong packet")
+					ap.log.WithError(err).Errorf("failed sending Pong packet")
 					break loop
 				}
 			case PacketTypePongAck:
-				log.Tracef("received accesspoint pong ack")
+				ap.log.Tracef("received accesspoint pong ack")
 				ap.lastPongAckLock.Lock()
 				ap.lastPongAck = time.Now()
 				ap.lastPongAckLock.Unlock()
@@ -297,7 +302,7 @@ loop:
 				}
 
 				if !handled {
-					log.Debugf("skipping packet %v, len: %d", pkt, len(payload))
+					ap.log.Debugf("skipping packet %v, len: %d", pkt, len(payload))
 				}
 			}
 		}
@@ -310,7 +315,7 @@ loop:
 	if !ap.stop {
 		ap.connMu.Lock()
 		if err := backoff.Retry(ap.reconnect, backoff.NewExponentialBackOff()); err != nil {
-			log.WithError(err).Errorf("failed reconnecting accesspoint, bye bye")
+			ap.log.WithError(err).Errorf("failed reconnecting accesspoint, bye bye")
 			log.Exit(1)
 		}
 		ap.connMu.Unlock()
@@ -347,7 +352,7 @@ loop:
 			timePassed := time.Since(ap.lastPongAck)
 			ap.lastPongAckLock.Unlock()
 			if timePassed > pongAckInterval {
-				log.Errorf("did not receive last pong ack from accesspoint, %.0fs passed", timePassed.Seconds())
+				ap.log.Errorf("did not receive last pong ack from accesspoint, %.0fs passed", timePassed.Seconds())
 
 				// closing the connection should make the read on the "recvLoop" fail,
 				// continue hoping for a new connection
@@ -376,7 +381,7 @@ func (ap *Accesspoint) reconnect() (err error) {
 	// if we are here the "recvLoop" has already died, restart it
 	go ap.recvLoop()
 
-	log.Debugf("re-established accesspoint connection")
+	ap.log.Debugf("re-established accesspoint connection")
 	return nil
 }
 
@@ -426,7 +431,7 @@ func (ap *Accesspoint) performKeyExchange() ([]byte, error) {
 	// exchange keys and compute shared secret
 	ap.dh.Exchange(apResponse.Challenge.LoginCryptoChallenge.DiffieHellman.Gs)
 
-	log.Debugf("completed keyexchange")
+	ap.log.Debugf("completed keyexchange")
 	return cc.Dump(), nil
 }
 
@@ -463,7 +468,7 @@ func (ap *Accesspoint) solveChallenge(exchangeData []byte) error {
 	var resp pb.APResponseMessage
 	if err := readMessage(ap.conn, &resp); errors.Is(err, os.ErrDeadlineExceeded) {
 		ap.encConn = newShannonConn(ap.conn, macData[20:52], macData[52:84])
-		log.Debug("completed challenge")
+		ap.log.Debug("completed challenge")
 		return nil
 	} else if err != nil {
 		return fmt.Errorf("failed reading APLoginFailed message: %w", err)
@@ -510,7 +515,7 @@ func (ap *Accesspoint) authenticate(ctx context.Context, credentials *pb.LoginCr
 		}
 
 		ap.welcome = &welcome
-		log.Infof("authenticated AP as %s", *welcome.CanonicalUsername)
+		ap.log.Infof("authenticated AP as %s", *welcome.CanonicalUsername)
 
 		return nil
 	} else if recvPkt == PacketTypeAuthFailure {

apresolve/resolve.go

@@ -21,6 +21,8 @@ type apResolveResponse struct {
 }
 
 type ApResolver struct {
+	log *log.Entry
+
 	baseUrl *url.URL
 
 	endpoints     map[endpointType][]string
@@ -30,13 +32,14 @@ type ApResolver struct {
 	client *http.Client
 }
 
-func NewApResolver(client *http.Client) *ApResolver {
+func NewApResolver(log *log.Entry, client *http.Client) *ApResolver {
 	baseUrl, err := url.Parse("https://apresolve.spotify.com/")
 	if err != nil {
 		panic("invalid apresolve base URL")
 	}
 
 	return &ApResolver{
+		log:          log,
 		baseUrl:      baseUrl,
 		client:       client,
 		endpoints:    map[endpointType][]string{},
@@ -100,17 +103,17 @@ func (r *ApResolver) fetchUrls(ctx context.Context, types ...endpointType) error
 	if slices.Contains(types, endpointTypeAccesspoint) {
 		r.endpoints[endpointTypeAccesspoint] = respJson.Accesspoint
 		r.endpointsExp[endpointTypeAccesspoint] = time.Now().Add(1 * time.Hour)
-		log.Debugf("fetched new accesspoints: %v", respJson.Accesspoint)
+		r.log.Debugf("fetched new accesspoints: %v", respJson.Accesspoint)
 	}
 	if slices.Contains(types, endpointTypeDealer) {
 		r.endpoints[endpointTypeDealer] = respJson.Dealer
 		r.endpointsExp[endpointTypeDealer] = time.Now().Add(1 * time.Hour)
-		log.Debugf("fetched new dealers: %v", respJson.Dealer)
+		r.log.Debugf("fetched new dealers: %v", respJson.Dealer)
 	}
 	if slices.Contains(types, endpointTypeSpclient) {
 		r.endpoints[endpointTypeSpclient] = respJson.Spclient
 		r.endpointsExp[endpointTypeSpclient] = time.Now().Add(1 * time.Hour)
-		log.Debugf("fetched new spclients: %v", respJson.Spclient)
+		r.log.Debugf("fetched new spclients: %v", respJson.Spclient)
 	}
 
 	return nil
@@ -155,7 +158,7 @@ func (r *ApResolver) getFunc(ctx context.Context, type_ endpointType) (librespot
 		newAddrs, err := r.get(innerCtx, type_)
 		if err != nil {
 			// if we cannot fetch new endpoints, eat it and return the first one
-			log.WithError(err).Warnf("failed fetching new endpoint for %s", type_)
+			r.log.WithError(err).Warnf("failed fetching new endpoint for %s", type_)
 			return addrs[0]
 		}
 

cmd/daemon/controls.go

@@ -140,7 +140,7 @@ func (p *AppPlayer) handlePlayerEvent(ctx context.Context, ev *player.Event) {
 type skipToFunc func(*connectpb.ContextTrack) bool
 
 func (p *AppPlayer) loadContext(ctx context.Context, spotCtx *connectpb.Context, skipTo skipToFunc, paused, drop bool) error {
-	ctxTracks, err := tracks.NewTrackListFromContext(ctx, p.sess.Spclient(), spotCtx)
+	ctxTracks, err := tracks.NewTrackListFromContext(ctx, p.app.log, p.sess.Spclient(), spotCtx)
 	if err != nil {
 		return fmt.Errorf("failed creating track list: %w", err)
 	}

cmd/daemon/main.go

@@ -36,6 +36,7 @@ import (
 var errAlreadyRunning = errors.New("go-librespot is already running")
 
 type App struct {
+	log *log.Entry
 	cfg *Config
 
 	client *http.Client
@@ -64,6 +65,7 @@ func parseDeviceType(val string) (devicespb.DeviceType, error) {
 func NewApp(cfg *Config) (app *App, err error) {
 	app = &App{cfg: cfg, logoutCh: make(chan *AppPlayer)}
 
+	app.log = log.NewEntry(log.StandardLogger())
 	app.client = &http.Client{}
 
 	app.deviceType, err = parseDeviceType(cfg.DeviceType)
@@ -75,7 +77,7 @@ func NewApp(cfg *Config) (app *App, err error) {
 		return nil, err
 	}
 
-	app.resolver = apresolve.NewApResolver(app.client)
+	app.resolver = apresolve.NewApResolver(app.log, app.client)
 
 	if cfg.DeviceId != "" {
 		// Use configured device ID.
@@ -118,6 +120,7 @@ func (app *App) newAppPlayer(ctx context.Context, creds any) (_ *AppPlayer, err
 	appPlayer.prefetchTimer = time.AfterFunc(time.Duration(math.MaxInt64), appPlayer.prefetchNext)
 
 	if appPlayer.sess, err = session.NewSessionFromOptions(ctx, &session.Options{
+		Log:         app.log,
 		DeviceType:  app.deviceType,
 		DeviceId:    app.deviceId,
 		ClientToken: app.clientToken,
@@ -230,7 +233,7 @@ func (app *App) withAppPlayer(ctx context.Context, appPlayerFunc func(context.Co
 	}
 
 	// start zeroconf server and dispatch
-	z, err := zeroconf.NewZeroconf(app.cfg.ZeroconfPort, app.cfg.DeviceName, app.deviceId, app.deviceType)
+	z, err := zeroconf.NewZeroconf(app.log, app.cfg.ZeroconfPort, app.cfg.DeviceName, app.deviceId, app.deviceType)
 	if err != nil {
 		return fmt.Errorf("failed initializing zeroconf: %w", err)
 	}

cmd/daemon/player.go

@@ -159,7 +159,7 @@ func (p *AppPlayer) handlePlayerCommand(ctx context.Context, req dealer.RequestP
 		}
 		p.state.lastTransferTimestamp = transferState.Playback.Timestamp
 
-		ctxTracks, err := tracks.NewTrackListFromContext(ctx, p.sess.Spclient(), transferState.CurrentSession.Context)
+		ctxTracks, err := tracks.NewTrackListFromContext(ctx, p.app.log, p.sess.Spclient(), transferState.CurrentSession.Context)
 		if err != nil {
 			return fmt.Errorf("failed creating track list: %w", err)
 		}

dealer/dealer.go

@@ -21,6 +21,8 @@ const (
 )
 
 type Dealer struct {
+	log *log.Entry
+
 	client *http.Client
 
 	addr        librespot.GetAddressFunc
@@ -46,14 +48,15 @@ type Dealer struct {
 	requestReceiversLock sync.RWMutex
 }
 
-func NewDealer(client *http.Client, dealerAddr librespot.GetAddressFunc, accessToken librespot.GetLogin5TokenFunc) *Dealer {
+func NewDealer(log *log.Entry, client *http.Client, dealerAddr librespot.GetAddressFunc, accessToken librespot.GetLogin5TokenFunc) *Dealer {
 	return &Dealer{
 		client: &http.Client{
 			Transport:     client.Transport,
 			CheckRedirect: client.CheckRedirect,
 			Jar:           client.Jar,
 			Timeout:       timeout,
 		},
+		log:              log,
 		addr:             dealerAddr,
 		accessToken:      accessToken,
 		requestReceivers: map[string]requestReceiver{},
@@ -65,7 +68,7 @@ func (d *Dealer) Connect(ctx context.Context) error {
 	defer d.connMu.Unlock()
 
 	if d.conn != nil && !d.stop {
-		log.Debugf("dealer connection already opened")
+		d.log.Debugf("dealer connection already opened")
 		return nil
 	}
 
@@ -97,7 +100,7 @@ func (d *Dealer) connect(ctx context.Context) error {
 	// remove the read limit
 	d.conn.SetReadLimit(math.MaxUint32)
 
-	log.Debugf("dealer connection opened")
+	d.log.Debugf("dealer connection opened")
 
 	return nil
 }
@@ -119,7 +122,7 @@ func (d *Dealer) Close() {
 
 func (d *Dealer) startReceiving() {
 	d.recvLoopOnce.Do(func() {
-		log.Tracef("starting dealer recv loop")
+		d.log.Tracef("starting dealer recv loop")
 		go d.recvLoop()
 
 		// set last pong in the future
@@ -141,7 +144,7 @@ loop:
 			timePassed := time.Since(d.lastPong)
 			d.lastPongLock.Unlock()
 			if timePassed > pingInterval+timeout {
-				log.Errorf("did not receive last pong from dealer, %.0fs passed", timePassed.Seconds())
+				d.log.Errorf("did not receive last pong from dealer, %.0fs passed", timePassed.Seconds())
 
 				// closing the connection should make the read on the "recvLoop" fail,
 				// continue hoping for a new connection
@@ -154,15 +157,15 @@ loop:
 			err := d.conn.Write(ctx, websocket.MessageText, []byte("{\"type\":\"ping\"}"))
 			d.connMu.RUnlock()
 			cancel()
-			log.Tracef("sent dealer ping")
+			d.log.Tracef("sent dealer ping")
 
 			if err != nil {
 				if d.stop {
 					// break early without logging if we should stop
 					break loop
 				}
 
-				log.WithError(err).Warnf("failed sending dealer ping")
+				d.log.WithError(err).Warnf("failed sending dealer ping")
 
 				// closing the connection should make the read on the "recvLoop" fail,
 				// continue hoping for a new connection
@@ -187,19 +190,19 @@ loop:
 
 			// don't log closed error if we're stopping
 			if d.stop && websocket.CloseStatus(err) == websocket.StatusGoingAway {
-				log.Debugf("dealer connection closed")
+				d.log.Debugf("dealer connection closed")
 				break loop
 			} else if err != nil {
-				log.WithError(err).Errorf("failed receiving dealer message")
+				d.log.WithError(err).Errorf("failed receiving dealer message")
 				break loop
 			} else if msgType != websocket.MessageText {
-				log.WithError(err).Warnf("unsupported message type: %v, len: %d", msgType, len(messageBytes))
+				d.log.WithError(err).Warnf("unsupported message type: %v, len: %d", msgType, len(messageBytes))
 				continue
 			}
 
 			var message RawMessage
 			if err := json.Unmarshal(messageBytes, &message); err != nil {
-				log.WithError(err).Error("failed unmarshalling dealer message")
+				d.log.WithError(err).Error("failed unmarshalling dealer message")
 				break loop
 			}
 
@@ -217,10 +220,10 @@ loop:
 				d.lastPongLock.Lock()
 				d.lastPong = time.Now()
 				d.lastPongLock.Unlock()
-				log.Tracef("received dealer pong")
+				d.log.Tracef("received dealer pong")
 				break
 			default:
-				log.Warnf("unknown dealer message type: %s", message.Type)
+				d.log.Warnf("unknown dealer message type: %s", message.Type)
 				break
 			}
 		}
@@ -233,7 +236,7 @@ loop:
 	if !d.stop {
 		d.connMu.Lock()
 		if err := backoff.Retry(d.reconnect, backoff.NewExponentialBackOff()); err != nil {
-			log.WithError(err).Errorf("failed reconnecting dealer, bye bye")
+			d.log.WithError(err).Errorf("failed reconnecting dealer, bye bye")
 			log.Exit(1)
 		}
 		d.connMu.Unlock()
@@ -254,7 +257,7 @@ loop:
 	}
 	d.messageReceiversLock.RUnlock()
 
-	log.Debugf("dealer recv loop stopped")
+	d.log.Debugf("dealer recv loop stopped")
 }
 
 func (d *Dealer) sendReply(key string, success bool) error {
@@ -289,6 +292,6 @@ func (d *Dealer) reconnect() error {
 	// restart the recv loop
 	go d.recvLoop()
 
-	log.Debugf("re-established dealer connection")
+	d.log.Debugf("re-established dealer connection")
 	return nil
 }