From e461e9cd795f36e7659882df542e90ba235e6a26 Mon Sep 17 00:00:00 2001
From: Raja Subramanian <raja.gobi@tutanota.com>
Date: Thu, 19 Oct 2023 13:58:50 +0530
Subject: [PATCH] Log skew in clock rate. (#2158)

* Log skew in clock rate.

Remember seeing sender report time stamp moving backward
across mute with replaceTrack(null). Not able to reproduce
it in JS sample app, but have seen it elsewhere.

Logging to understand it better. Wondering if the sender report
should be reset on time stamp moving backward or if we should drop
backwards moving reports.

* set threshold at 20%
---
 pkg/sfu/buffer/rtpstats_base.go     | 12 +++++++++
 pkg/sfu/buffer/rtpstats_receiver.go | 39 ++++++++++++++++++-----------
 2 files changed, 37 insertions(+), 14 deletions(-)

diff --git a/pkg/sfu/buffer/rtpstats_base.go b/pkg/sfu/buffer/rtpstats_base.go
index 0c77299ae..11b89b9cc 100644
--- a/pkg/sfu/buffer/rtpstats_base.go
+++ b/pkg/sfu/buffer/rtpstats_base.go
@@ -105,6 +105,8 @@ type snapshot struct {
 	maxJitter float64
 }
 
+// ------------------------------------------------------------------
+
 type RTCPSenderReportData struct {
 	RTPTimestamp    uint32
 	RTPTimestampExt uint64
@@ -112,6 +114,16 @@ type RTCPSenderReportData struct {
 	At              time.Time
 }
 
+func (r *RTCPSenderReportData) ToString() string {
+	if r == nil {
+		return ""
+	}
+
+	return fmt.Sprintf("ntp: %s, rtp: %d, extRtp: %d, at: %s", r.NTPTimestamp.Time().String(), r.RTPTimestamp, r.RTPTimestampExt, r.At.String())
+}
+
+// ------------------------------------------------------------------
+
 type RTPStatsParams struct {
 	ClockRate uint32
 	Logger    logger.Logger
diff --git a/pkg/sfu/buffer/rtpstats_receiver.go b/pkg/sfu/buffer/rtpstats_receiver.go
index 5902f57e8..fe906eb98 100644
--- a/pkg/sfu/buffer/rtpstats_receiver.go
+++ b/pkg/sfu/buffer/rtpstats_receiver.go
@@ -16,6 +16,7 @@ package buffer
 
 import (
 	"fmt"
+	"math"
 	"time"
 
 	"github.com/pion/rtcp"
@@ -287,12 +288,8 @@ func (r *RTPStatsReceiver) SetRtcpSenderReportData(srData *RTCPSenderReportData)
 	if r.srNewest != nil && r.srNewest.NTPTimestamp > srData.NTPTimestamp {
 		r.logger.Infow(
 			"received anachronous sender report",
-			"currentNTP", srData.NTPTimestamp.Time().String(),
-			"currentRTP", srData.RTPTimestamp,
-			"currentAt", srData.At.String(),
-			"lastNTP", r.srNewest.NTPTimestamp.Time().String(),
-			"lastRTP", r.srNewest.RTPTimestamp,
-			"lastAt", r.srNewest.At.String(),
+			"last", r.srNewest.ToString(),
+			"current", srData.ToString(),
 		)
 		return
 	}
@@ -310,6 +307,26 @@ func (r *RTPStatsReceiver) SetRtcpSenderReportData(srData *RTCPSenderReportData)
 
 	r.maybeAdjustFirstPacketTime(srDataCopy.RTPTimestamp, r.timestamp.GetStart())
 
+	if r.srNewest != nil {
+		timeSinceLast := srData.NTPTimestamp.Time().Sub(r.srNewest.NTPTimestamp.Time()).Seconds()
+		rtpDiffSinceLast := srDataCopy.RTPTimestampExt - r.srNewest.RTPTimestampExt
+		calculatedClockRateFromLast := float64(rtpDiffSinceLast) / timeSinceLast
+
+		timeSinceFirst := srData.NTPTimestamp.Time().Sub(r.srFirst.NTPTimestamp.Time()).Seconds()
+		rtpDiffSinceFirst := srDataCopy.RTPTimestampExt - r.srFirst.RTPTimestampExt
+		calculatedClockRateFromFirst := float64(rtpDiffSinceFirst) / timeSinceFirst
+		if math.Abs(float64(r.params.ClockRate)-calculatedClockRateFromLast) > 0.2*float64(r.params.ClockRate) || math.Abs(float64(r.params.ClockRate)-calculatedClockRateFromFirst) > 0.2*float64(r.params.ClockRate) {
+			r.logger.Infow(
+				"clock rate skew",
+				"first", r.srFirst.ToString(),
+				"last", r.srNewest.ToString(),
+				"current", srDataCopy.ToString(),
+				"calculatedFirst", calculatedClockRateFromFirst,
+				"calculatedLast", calculatedClockRateFromLast,
+			)
+		}
+	}
+
 	if r.srNewest != nil && srDataCopy.RTPTimestampExt < r.srNewest.RTPTimestampExt {
 		// This can happen when a track is replaced with a null and then restored -
 		// i. e. muting replacing with null and unmute restoring the original track.
@@ -317,14 +334,8 @@ func (r *RTPStatsReceiver) SetRtcpSenderReportData(srData *RTCPSenderReportData)
 		// Resetting will ensure sample rate calculations do not go haywire due to negative time.
 		r.logger.Infow(
 			"received sender report, out-of-order, resetting",
-			"prevTSExt", r.srNewest.RTPTimestampExt,
-			"prevRTP", r.srNewest.RTPTimestamp,
-			"prevNTP", r.srNewest.NTPTimestamp.Time().String(),
-			"prevAt", r.srNewest.At.String(),
-			"currTSExt", srDataCopy.RTPTimestampExt,
-			"currRTP", srDataCopy.RTPTimestamp,
-			"currNTP", srDataCopy.NTPTimestamp.Time().String(),
-			"currentAt", srDataCopy.At.String(),
+			"last", r.srNewest.ToString(),
+			"current", srDataCopy.ToString(),
 		)
 		r.srFirst = nil
 	}