From 66de9ff4a0c2c9a3832d61bf3b9383b40bcc3713 Mon Sep 17 00:00:00 2001
From: Raja Subramanian <raja.gobi@tutanota.com>
Date: Tue, 18 Jul 2023 23:21:06 +0530
Subject: [PATCH] Add debug log for RTCP sender report. (#1890)

* Add debug log for RTCP sender report.

Temporary to collect more data. Hitting scenarios under congestion
where the sender report gets off sync. Need some data to pore through
and understand and implement changes.

* Debugw
---
 pkg/sfu/buffer/rtpstats.go | 19 +++++++++++++++++++
 pkg/sfu/downtrack.go       |  6 +++++-
 pkg/sfu/forwarder.go       | 19 +++++++++++++++++++
 3 files changed, 43 insertions(+), 1 deletion(-)

diff --git a/pkg/sfu/buffer/rtpstats.go b/pkg/sfu/buffer/rtpstats.go
index 1774eb28c..f5bb0a5d9 100644
--- a/pkg/sfu/buffer/rtpstats.go
+++ b/pkg/sfu/buffer/rtpstats.go
@@ -944,6 +944,25 @@ func (r *RTPStats) GetRtcpSenderReport(ssrc uint32, calculatedClockRate uint32)
 			"nowRTPExt", nowRTPExt,
 			"nowRTPExtUsingRate", nowRTPExtUsingRate,
 		)
+	} else {
+		packetDriftResult, reportDriftResult := r.getDrift()
+		r.logger.Debugw(
+			"sending sender report",
+			"ntp", nowNTP.Time().String(),
+			"rtp", nowRTP,
+			"departure", now.String(),
+			"ntpDiffSinceLast", ntpDiffSinceLast.Seconds(),
+			"rtpDiffSinceLast", int32(rtpDiffSinceLast),
+			"departureDiffSinceLast", departureDiffSinceLast.Seconds(),
+			"expectedTimeDiffSinceLast", expectedTimeDiffSinceLast,
+			"packetDrift", packetDriftResult.String(),
+			"reportDrift", reportDriftResult.String(),
+			"highestTS", r.highestTS,
+			"highestTime", r.highestTime.String(),
+			"calculatedClockRate", calculatedClockRate,
+			"nowRTPExt", nowRTPExt,
+			"nowRTPExtUsingRate", nowRTPExtUsingRate,
+		)
 	}
 
 	return &rtcp.SenderReport{
diff --git a/pkg/sfu/downtrack.go b/pkg/sfu/downtrack.go
index e21a001f9..d943b7c75 100644
--- a/pkg/sfu/downtrack.go
+++ b/pkg/sfu/downtrack.go
@@ -1165,7 +1165,11 @@ func (d *DownTrack) CreateSenderReport() *rtcp.SenderReport {
 		return nil
 	}
 
-	return d.rtpStats.GetRtcpSenderReport(d.ssrc, d.receiver.GetCalculatedClockRate(d.forwarder.CurrentLayer().Spatial))
+	clockLayer := d.forwarder.CurrentLayer().Spatial
+	if clockLayer == buffer.InvalidLayerSpatial {
+		clockLayer = d.forwarder.GetReferenceLayerSpatial()
+	}
+	return d.rtpStats.GetRtcpSenderReport(d.ssrc, d.receiver.GetCalculatedClockRate(clockLayer))
 }
 
 func (d *DownTrack) writeBlankFrameRTP(duration float32, generation uint32) chan struct{} {
diff --git a/pkg/sfu/forwarder.go b/pkg/sfu/forwarder.go
index 23a8d694d..79b2b48c1 100644
--- a/pkg/sfu/forwarder.go
+++ b/pkg/sfu/forwarder.go
@@ -529,6 +529,13 @@ func (f *Forwarder) GetMaxSubscribedSpatial() int32 {
 	return layer
 }
 
+func (f *Forwarder) GetReferenceLayerSpatial() int32 {
+	f.lock.RLock()
+	defer f.lock.RUnlock()
+
+	return f.referenceLayerSpatial
+}
+
 func (f *Forwarder) isDeficientLocked() bool {
 	return f.lastAllocation.IsDeficient
 }
@@ -1970,6 +1977,18 @@ done:
 	if !targetLayer.IsValid() {
 		distance += (maxSeenLayer.Temporal + 1)
 	}
+	// TODO-REMOVE-AFTER-DEBUG
+	logger.Debugw(
+		"distance to desired",
+		"maxSeenLauer", maxSeenLayer,
+		"availableLayers", availableLayers,
+		"brs", brs,
+		"targetLayer", targetLayer,
+		"maxLayer", maxLayer,
+		"adjustedMaxLayer", adjustedMaxLayer,
+		"maxAvailableSpatial", maxAvailableSpatial,
+		"maxAvailableTemporal", maxAvailableTemporal,
+	)
 
 	return float64(distance) / float64(maxSeenLayer.Temporal+1)
 }