Promoting a few logs to Info (#921)

* Promoting a few logs to Info

Also, adding a couple of more info logs which I will remove later
after some debugging.

* mime type

* Protect pause/max layer

* notify even if not bound

pkg/rtc/dynacastmanager.go

@@ -174,6 +174,12 @@ func (d *DynacastManager) updateMaxQualityForMime(mime string, maxQuality liveki
 func (d *DynacastManager) update(force bool) {
 	d.lock.Lock()
 
+	d.params.Logger.Infow("processing quality change",
+		"force", force,
+		"committedMaxSubscribedQuality", d.committedMaxSubscribedQuality,
+		"maxSubscribedQuality", d.maxSubscribedQuality,
+	)
+
 	if len(d.maxSubscribedQuality) == 0 {
 		// no mime has been added, nothing to update
 		d.lock.Unlock()
@@ -204,7 +210,7 @@ func (d *DynacastManager) update(force bool) {
 		}
 
 		if downgradesOnly {
-			d.params.Logger.Debugw("debouncing quality downgrade",
+			d.params.Logger.Infow("debouncing quality downgrade",
 				"committedMaxSubscribedQuality", d.committedMaxSubscribedQuality,
 				"maxSubscribedQuality", d.maxSubscribedQuality,
 			)

pkg/rtc/dynacastquality.go

@@ -58,6 +58,7 @@ func (d *DynacastQuality) OnSubscribedMaxQualityChange(f func(maxSubscribedQuali
 }
 
 func (d *DynacastQuality) NotifySubscriberMaxQuality(subscriberID livekit.ParticipantID, quality livekit.VideoQuality) {
+	d.params.Logger.Infow("setting subscriber max quality", "mime", d.params.MimeType, "subscriberID", subscriberID, "quality", quality.String())
 	d.lock.Lock()
 	if quality == livekit.VideoQuality_OFF {
 		delete(d.maxSubscriberQuality, subscriberID)
@@ -70,6 +71,7 @@ func (d *DynacastQuality) NotifySubscriberMaxQuality(subscriberID livekit.Partic
 }
 
 func (d *DynacastQuality) NotifySubscriberNodeMaxQuality(nodeID livekit.NodeID, quality livekit.VideoQuality) {
+	d.params.Logger.Infow("setting subscriber node max quality", "mime", d.params.MimeType, "subscriberNodeID", nodeID, "quality", quality.String())
 	d.lock.Lock()
 	if quality == livekit.VideoQuality_OFF {
 		delete(d.maxSubscriberNodeQuality, nodeID)
@@ -115,6 +117,7 @@ func (d *DynacastQuality) updateQualityChange(force bool) {
 		"maxSubscriberQuality", d.maxSubscriberQuality,
 		"maxSubscriberNodeQuality", d.maxSubscriberNodeQuality,
 		"maxSubscribedQuality", d.maxSubscribedQuality,
+		"force", force,
 	)
 	onSubscribedMaxQualityChange := d.onSubscribedMaxQualityChange
 	d.lock.Unlock()

pkg/rtc/signalhandler.go

@@ -56,6 +56,10 @@ func HandleParticipantSignal(room types.Room, participant types.LocalParticipant
 			pLogger.Warnw("could not update subscription", err,
 				"tracks", msg.Subscription.TrackSids,
 				"subscribe", msg.Subscription.Subscribe)
+		} else {
+			pLogger.Infow("updated subscription",
+				"tracks", msg.Subscription.TrackSids,
+				"subscribe", msg.Subscription.Subscribe)
 		}
 	case *livekit.SignalRequest_TrackSetting:
 		for _, sid := range livekit.StringsAsTrackIDs(msg.TrackSetting.TrackSids) {

pkg/rtc/uptrackmanager.go

@@ -170,7 +170,7 @@ func (u *UpTrackManager) SetPublishedTrackMuted(trackID livekit.TrackID, muted b
 		track.SetMuted(muted)
 
 		if currentMuted != track.IsMuted() {
-			u.params.Logger.Debugw("mute status changed", "trackID", trackID, "muted", track.IsMuted())
+			u.params.Logger.Infow("mute status changed", "trackID", trackID, "muted", track.IsMuted())
 			if u.onTrackUpdated != nil {
 				u.onTrackUpdated(track, false)
 			}
@@ -232,7 +232,7 @@ func (u *UpTrackManager) UpdateSubscriptionPermission(
 	// store as is for use when migrating
 	u.subscriptionPermission = subscriptionPermission
 	if subscriptionPermission == nil {
-		u.params.Logger.Debugw(
+		u.params.Logger.Infow(
 			"updating subscription permission, setting to nil",
 			"version", u.subscriptionPermissionVersion.ToProto().String(),
 		)
@@ -241,7 +241,7 @@ func (u *UpTrackManager) UpdateSubscriptionPermission(
 		return nil
 	}
 
-	u.params.Logger.Debugw(
+	u.params.Logger.Infow(
 		"updating subscription permission",
 		"permissions", u.subscriptionPermission.String(),
 		"version", u.subscriptionPermissionVersion.ToProto().String(),

pkg/rtc/wrappedreceiver.go

@@ -109,6 +109,7 @@ func (d *DummyReceiver) Upgrade(receiver sfu.TrackReceiver) {
 		receiver.SetMaxExpectedSpatialLayer(d.maxExpectedLayer)
 	}
 	d.maxExpectedLayerValid = false
+
 	if d.pausedValid {
 		receiver.SetUpTrackPaused(d.paused)
 	}
@@ -166,24 +167,26 @@ func (d *DummyReceiver) SendPLI(layer int32, force bool) {
 }
 
 func (d *DummyReceiver) SetUpTrackPaused(paused bool) {
+	d.settingsLock.Lock()
+	defer d.settingsLock.Unlock()
 	if r, ok := d.receiver.Load().(sfu.TrackReceiver); ok {
+		d.pausedValid = false
 		r.SetUpTrackPaused(paused)
 	} else {
-		d.settingsLock.Lock()
 		d.pausedValid = true
 		d.paused = paused
-		d.settingsLock.Unlock()
 	}
 }
 
 func (d *DummyReceiver) SetMaxExpectedSpatialLayer(layer int32) {
+	d.settingsLock.Lock()
+	defer d.settingsLock.Unlock()
 	if r, ok := d.receiver.Load().(sfu.TrackReceiver); ok {
+		d.maxExpectedLayerValid = false
 		r.SetMaxExpectedSpatialLayer(layer)
 	} else {
-		d.settingsLock.Lock()
 		d.maxExpectedLayerValid = true
 		d.maxExpectedLayer = layer
-		d.settingsLock.Unlock()
 	}
 }
 

pkg/sfu/downtrack.go

@@ -597,6 +597,7 @@ func (d *DownTrack) WritePaddingRTP(bytesToSend int) int {
 
 // Mute enables or disables media forwarding
 func (d *DownTrack) Mute(muted bool) {
+	d.logger.Infow("setting mute", "muted", muted)
 	changed, maxLayers := d.forwarder.Mute(muted)
 	if !changed {
 		return
@@ -694,13 +695,13 @@ func (d *DownTrack) CloseWithFlush(flush bool) {
 }
 
 func (d *DownTrack) SetMaxSpatialLayer(spatialLayer int32) {
+	d.logger.Infow("setting max spatial layer", "layer", spatialLayer)
 	changed, maxLayers, currentLayers := d.forwarder.SetMaxSpatialLayer(spatialLayer)
 	if !changed {
 		return
 	}
 
-	if d.onMaxLayerChanged != nil && d.kind == webrtc.RTPCodecTypeVideo &&
-		maxLayers.SpatialGreaterThanOrEqual(currentLayers) && d.bound.Load() {
+	if d.onMaxLayerChanged != nil && d.kind == webrtc.RTPCodecTypeVideo && maxLayers.SpatialGreaterThanOrEqual(currentLayers) {
 		//
 		// Notify when new max is
 		//   1. Equal to current -> already locked to the new max