From 0407eb4833f35ec77c1e272bb519dd6eff8a5e49 Mon Sep 17 00:00:00 2001
From: Raja Subramanian <raja.gobi@tutanota.com>
Date: Sat, 21 Oct 2023 01:37:30 +0530
Subject: [PATCH] Log audio packets in forwarding path. (#2162)

Seeing a time stamp jump that I am not able to explain.
Basically, it looks like the time stamp doubles at some
point. There is no code which doubles the timestamp.
Can understand an erroneous roll over/wrap around, but
doubling is very strange.

So, logging only audio packets. Will disable as soon
as I have some smaples from canary.
---
 pkg/sfu/buffer/rtpstats_sender.go | 2 ++
 pkg/sfu/downtrack.go              | 8 ++++++++
 pkg/sfu/forwarder.go              | 2 +-
 pkg/sfu/rtpmunger.go              | 3 +++
 4 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/pkg/sfu/buffer/rtpstats_sender.go b/pkg/sfu/buffer/rtpstats_sender.go
index 49892afdb..47bf2411b 100644
--- a/pkg/sfu/buffer/rtpstats_sender.go
+++ b/pkg/sfu/buffer/rtpstats_sender.go
@@ -610,6 +610,7 @@ func (r *RTPStatsSender) GetRtcpSenderReport(ssrc uint32, calculatedClockRate ui
 				"last", r.srNewest.ToString(),
 				"curr", srData.ToString(),
 				"timeNow", time.Now().String(),
+				"extStartTS", r.extStartTS,
 				"extHighestTS", r.extHighestTS,
 				"highestTime", r.highestTime.String(),
 				"timeSinceHighest", timeSinceHighest.String(),
@@ -642,6 +643,7 @@ func (r *RTPStatsSender) GetRtcpSenderReport(ssrc uint32, calculatedClockRate ui
 			"last", r.srNewest.ToString(),
 			"curr", srData.ToString(),
 			"timeNow", time.Now().String(),
+			"extStartTS", r.extStartTS,
 			"extHighestTS", r.extHighestTS,
 			"highestTime", r.highestTime.String(),
 			"timeSinceHighest", timeSinceHighest.String(),
diff --git a/pkg/sfu/downtrack.go b/pkg/sfu/downtrack.go
index b26080526..c37cb7b21 100644
--- a/pkg/sfu/downtrack.go
+++ b/pkg/sfu/downtrack.go
@@ -743,6 +743,14 @@ func (d *DownTrack) WriteRTP(extPkt *buffer.ExtPacket, layer int32) error {
 		Pool:               PacketFactory,
 		PoolEntity:         poolEntity,
 	})
+	if d.kind == webrtc.RTPCodecTypeAudio {
+		d.params.Logger.Infow("forwarding debug",
+			"incomingSN", extPkt.ExtSequenceNumber,
+			"outgoingSN", tp.rtp.extSequenceNumber,
+			"incomingTS", extPkt.ExtTimestamp,
+			"outgoingTS", tp.rtp.extTimestamp,
+		) // TODO-REMOVE-AFTER-DEBUG
+	}
 	return nil
 }
 
diff --git a/pkg/sfu/forwarder.go b/pkg/sfu/forwarder.go
index ea6ea29c1..b174a2e9a 100644
--- a/pkg/sfu/forwarder.go
+++ b/pkg/sfu/forwarder.go
@@ -1479,7 +1479,7 @@ func (f *Forwarder) processSourceSwitch(extPkt *buffer.ExtPacket, layer int32) e
 	}
 
 	logTransition := func(message string, extExpectedTS, extRefTS, extLastTS uint64, diffSeconds float64) {
-		f.logger.Debugw(
+		f.logger.Infow(
 			message,
 			"layer", layer,
 			"extExpectedTS", extExpectedTS,
diff --git a/pkg/sfu/rtpmunger.go b/pkg/sfu/rtpmunger.go
index 31c415f12..636375d42 100644
--- a/pkg/sfu/rtpmunger.go
+++ b/pkg/sfu/rtpmunger.go
@@ -179,6 +179,9 @@ func (r *RTPMunger) UpdateAndGetSnTs(extPkt *buffer.ExtPacket) (*TranslationPara
 
 		extMungedSN := extPkt.ExtSequenceNumber - r.snOffset
 		extMungedTS := extPkt.ExtTimestamp - r.tsOffset
+		if extMungedTS > (r.extLastTS + 48000) {
+			r.logger.Infow("large jump in ts", "lastTS", r.extLastTS, "incomingTS", extPkt.ExtTimestamp, "mungedTS", extMungedTS, "tsOffset", r.tsOffset) // TODO-REMOVE-AFTER-DEBUG
+		}
 
 		r.extSecondLastSN = r.extLastSN
 		r.extLastSN = extMungedSN