From 3070e976c3f2ed5669695eddb69b3119b6f6f0d6 Mon Sep 17 00:00:00 2001
From: Raja Subramanian <raja.gobi@tutanota.com>
Date: Tue, 2 May 2023 00:22:33 +0530
Subject: [PATCH] Log received sender report of audio for debugging (#1673)

* Log received sender report of audio for debugging

* log OWD also

* add some more bits
---
 pkg/sfu/buffer/rtpstats.go | 43 ++++++++++++++++++++++++++++----------
 pkg/sfu/forwarder.go       |  1 +
 2 files changed, 33 insertions(+), 11 deletions(-)

diff --git a/pkg/sfu/buffer/rtpstats.go b/pkg/sfu/buffer/rtpstats.go
index ac1e421ed..0e17414e1 100644
--- a/pkg/sfu/buffer/rtpstats.go
+++ b/pkg/sfu/buffer/rtpstats.go
@@ -750,15 +750,27 @@ func (r *RTPStats) SetRtcpSenderReportData(srData *RTCPSenderReportData) {
 	if r.srDataExt != nil {
 		smoothedOwd = r.srDataExt.SmoothedOWD
 	}
+	smoothedOwd = (owd + smoothedOwd) / 2
+	// TODO-REMOVE-AFTER-DEBUG
+	if r.params.ClockRate != 90000 { // log only for audio as it is less frequent
+		r.logger.Debugw(
+			"received sender report",
+			"ntp", srData.NTPTimestamp.Time(),
+			"rtp", srData.RTPTimestamp,
+			"arrival", srData.ArrivalTime,
+			"owd", owd,
+			"smoothedOwd", smoothedOwd,
+		)
+	}
 	r.srDataExt = &RTCPSenderReportDataExt{
 		SenderReportData: *srData,
-		SmoothedOWD:      (owd + smoothedOwd) / 2,
+		SmoothedOWD:      smoothedOwd,
 	}
 }
 
 func (r *RTPStats) GetRtcpSenderReportDataExt() *RTCPSenderReportDataExt {
-	r.lock.Lock()
-	defer r.lock.Unlock()
+	r.lock.RLock()
+	defer r.lock.RUnlock()
 
 	if r.srDataExt == nil {
 		return nil
@@ -815,9 +827,14 @@ func (r *RTPStats) GetRtcpSenderReport(ssrc uint32, srDataExt *RTCPSenderReportD
 	} else {
 		highestTime := time.Unix(0, r.highestTime)
 		ntpTime := nowNTP.Time()
-		ntpDiff := ntpTime.Sub(highestTime)
-		rtpDiff := int32(nowRTP - r.highestTS)
-		rtpOffset := int32(nowRTP - r.highestTS - uint32(ntpDiff.Nanoseconds()*int64(r.params.ClockRate)/1e9))
+
+		ntpDiffLocal := ntpTime.Sub(highestTime)
+		rtpDiffLocal := int32(nowRTP - r.highestTS)
+		rtpOffsetLocal := int32(nowRTP - r.highestTS - uint32(ntpDiffLocal.Nanoseconds()*int64(r.params.ClockRate)/1e9))
+
+		ntpDiffSmoothed := ntpTime.Sub(smoothedLocalTimeOfLatestSenderReportNTP)
+		rtpDiffSmoothed := int32(nowRTP - srDataExt.SenderReportData.RTPTimestamp)
+		rtpOffsetSmoothed := int32(nowRTP - srDataExt.SenderReportData.RTPTimestamp - uint32(ntpDiffSmoothed.Nanoseconds()*int64(r.params.ClockRate)/1e9))
 
 		timeSinceFirst := nowNTP.Time().Sub(r.firstSenderReportNTP.Time())
 		rtpDiffSinceFirst := getExtTS(nowRTP, r.tsCycles) - getExtTS(r.firstSenderReportRTP, 0)
@@ -831,14 +848,18 @@ func (r *RTPStats) GetRtcpSenderReport(ssrc uint32, srDataExt *RTCPSenderReportD
 		feedDriftTime := (float64(feedDrift) * 1000) / float64(r.params.ClockRate)
 
 		r.logger.Debugw(
-			"sender report",
+			"sending sender report",
 			"highestTS", r.highestTS,
-			"reportTS", nowRTP,
-			"rtpDiff", rtpDiff,
 			"highestTime", highestTime,
+			"smoothedTime", smoothedLocalTimeOfLatestSenderReportNTP,
+			"reportTS", nowRTP,
 			"reportTime", ntpTime,
-			"timeDiff", ntpDiff,
-			"rtpOffset", rtpOffset,
+			"rtpDiffLocal", rtpDiffLocal,
+			"ntpDiffLocal", ntpDiffLocal,
+			"rtpOffsetLocal", rtpOffsetLocal,
+			"rtpDiffSmoothed", rtpDiffSmoothed,
+			"ntpDiffSmoothed", ntpDiffSmoothed,
+			"rtpOffsetSmoothed", rtpOffsetSmoothed,
 			"timeSinceFirst", timeSinceFirst,
 			"rtpDiffSinceFirst", rtpDiffSinceFirst,
 			"drift", drift,
diff --git a/pkg/sfu/forwarder.go b/pkg/sfu/forwarder.go
index 069132850..4c1ba5028 100644
--- a/pkg/sfu/forwarder.go
+++ b/pkg/sfu/forwarder.go
@@ -1459,6 +1459,7 @@ func (f *Forwarder) getTranslationParamsCommon(extPkt *buffer.ExtPacket, layer i
 						// log jumps greater than 0.5 seconds
 						f.logger.Debugw("reference timestamp too far ahead", "lastTS", last.LastTS, "refTS", refTS, "td", td)
 					}
+					f.logger.Debugw("reference timestamp on switch", "lastTS", last.LastTS, "refTS", refTS, "td", int32(td), "switchingAt", time.Now())
 				} else {
 					f.logger.Debugw("reference timestamp get error, using default", "error", err)
 				}