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

@@ -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(),

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
 }
 

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,

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