Adding some logs in subscribe path. (#2343)

Trying to chase down an older client failing to subscribe some times.

pkg/rtc/mediatracksubscriptions.go

@@ -207,6 +207,12 @@ func (t *MediaTrackSubscriptions) AddSubscriber(sub types.LocalParticipant, wr *
 	replacedTrack := false
 	existingTransceiver, dtState = sub.GetCachedDownTrack(trackID)
 	if existingTransceiver != nil {
+		sub.GetLogger().Debugw(
+			"trying to use existing transceiver",
+			"publisher", subTrack.PublisherIdentity(),
+			"publisherID", subTrack.PublisherID(),
+			"trackID", trackID,
+		)
 		reusingTransceiver.Store(true)
 		rtpSender := existingTransceiver.Sender()
 		if rtpSender != nil {
@@ -217,6 +223,12 @@ func (t *MediaTrackSubscriptions) AddSubscriber(sub types.LocalParticipant, wr *
 				sender = rtpSender
 				transceiver = existingTransceiver
 				replacedTrack = true
+				sub.GetLogger().Debugw(
+					"track replaced",
+					"publisher", subTrack.PublisherIdentity(),
+					"publisherID", subTrack.PublisherID(),
+					"trackID", trackID,
+				)
 			}
 		}
 

pkg/rtc/subscriptionmanager.go

@@ -505,8 +505,17 @@ func (m *SubscriptionManager) subscribe(s *trackSubscription) error {
 	subTrack, err := track.AddSubscriber(m.params.Participant)
 	if err != nil && err != errAlreadySubscribed {
 		// ignore already subscribed error
+		m.params.Logger.Warnw("add subscriber failed", err, "trackID", trackID)
 		return err
 	}
+	if err == errAlreadySubscribed {
+		m.params.Logger.Debugw(
+			"already subscribed to track",
+			"trackID", trackID,
+			"subscribedAudioCount", m.subscribedAudioCount.Load(),
+			"subscribedVideoCount", m.subscribedVideoCount.Load(),
+		)
+	}
 	if err == nil && subTrack != nil { // subTrack could be nil if already subscribed
 		subTrack.OnClose(func(willBeResumed bool) {
 			m.handleSubscribedTrackClose(s, willBeResumed)
@@ -536,9 +545,14 @@ func (m *SubscriptionManager) subscribe(s *trackSubscription) error {
 		}
 
 		go m.params.OnTrackSubscribed(subTrack)
-	}
 
-	m.params.Logger.Debugw("subscribed to track", "trackID", trackID, "subscribedAudioCount", m.subscribedAudioCount.Load(), "subscribedVideoCount", m.subscribedVideoCount.Load())
+		m.params.Logger.Debugw(
+			"subscribed to track",
+			"trackID", trackID,
+			"subscribedAudioCount", m.subscribedAudioCount.Load(),
+			"subscribedVideoCount", m.subscribedVideoCount.Load(),
+		)
+	}
 
 	// add mark the participant as someone we've subscribed to
 	firstSubscribe := false
@@ -596,7 +610,8 @@ func (m *SubscriptionManager) handleSourceTrackRemoved(trackID livekit.TrackID)
 // - UpTrack was closed
 // - publisher revoked permissions for the participant
 func (m *SubscriptionManager) handleSubscribedTrackClose(s *trackSubscription, willBeResumed bool) {
-	s.logger.Debugw("subscribed track closed",
+	s.logger.Debugw(
+		"subscribed track closed",
 		"willBeResumed", willBeResumed,
 	)
 	wasBound := s.isBound()

pkg/sfu/downtrack.go

@@ -351,6 +351,7 @@ func NewDownTrack(params DowntrackParams) (*DownTrack, error) {
 		go d.maxLayerNotifierWorker()
 		go d.keyFrameRequester()
 	}
+	d.params.Logger.Debugw("downtrack created")
 
 	return d, nil
 }