From 73ae58bb42479451fd4d1d8a8e961f9766773a74 Mon Sep 17 00:00:00 2001
From: Raja Subramanian <raja.gobi@tutanota.com>
Date: Wed, 6 Apr 2022 06:30:26 +0530
Subject: [PATCH] Reduce chatty logs (#592)

---
 pkg/sfu/buffer/buffer.go   |  1 -
 pkg/sfu/buffer/rtpstats.go | 37 -------------------------------------
 pkg/sfu/downtrack.go       |  3 +++
 pkg/sfu/testutils/data.go  |  9 ++++-----
 4 files changed, 7 insertions(+), 43 deletions(-)

diff --git a/pkg/sfu/buffer/buffer.go b/pkg/sfu/buffer/buffer.go
index e3dce2c60..a20419900 100644
--- a/pkg/sfu/buffer/buffer.go
+++ b/pkg/sfu/buffer/buffer.go
@@ -461,7 +461,6 @@ func (b *Buffer) getExtPacket(rawPacket []byte, rtpPacket *rtp.Packet, arrivalTi
 		ep.KeyFrame = IsAV1Keyframe(rtpPacket.Payload)
 	}
 	if ep.KeyFrame {
-		b.logger.Debugw("key frame received")
 		if b.rtpStats != nil {
 			b.rtpStats.UpdateKeyFrame(1)
 		}
diff --git a/pkg/sfu/buffer/rtpstats.go b/pkg/sfu/buffer/rtpstats.go
index 16bd6e6c1..ae5c7b8ff 100644
--- a/pkg/sfu/buffer/rtpstats.go
+++ b/pkg/sfu/buffer/rtpstats.go
@@ -176,7 +176,6 @@ func (r *RTPStats) Update(rtph *rtp.Header, payloadSize int, paddingSize int, pa
 		r.highestTime = packetTime
 
 		r.extStartSN = uint32(rtph.SequenceNumber)
-		r.logger.Debugw("RTPSTATS_DEBUG, setting extStartSN init", "extStartSN", r.extStartSN) // LK-DEBUG-REMOVE
 		r.cycles = 0
 
 		first = true
@@ -211,24 +210,6 @@ func (r *RTPStats) Update(rtph *rtp.Header, payloadSize int, paddingSize int, pa
 			flowState.LossStartInclusive = r.highestSN + 1
 			flowState.LossEndExclusive = rtph.SequenceNumber
 		}
-		// LK-DEBUG-REMOVE START
-		if diff > 100 {
-			r.logger.Debugw(
-				"RTPSTATS_DEBUG huge difference in sequence number",
-				"diff", diff,
-				"highestSN", r.highestSN,
-				"sn", rtph.SequenceNumber,
-				"startSN", r.extStartSN,
-				"lost", r.packetsLost,
-				"highestTS", r.highestTS,
-				"ts", rtph.Timestamp,
-				"tsDiff", rtph.Timestamp-r.highestTS,
-				"highestTime", r.highestTime,
-				"now", packetTime,
-				"timeDiff(ms)", float64(packetTime-r.highestTime)/1e6,
-			)
-		}
-		// LK-DEBUG-REMOVE END
 
 		// update gap histogram
 		r.updateGapHistogram(int(diff))
@@ -277,27 +258,9 @@ func (r *RTPStats) maybeAdjustStartSN(rtph *rtp.Header, packetTime int64) {
 		return
 	}
 
-	// LK-DEBUG-REMOVE START
-	r.logger.Debugw(
-		"RTPSTATS_DEBUG moving starting SN back",
-		"diff", rtph.SequenceNumber-uint16(r.extStartSN),
-		"loss added", uint16(r.extStartSN)-rtph.SequenceNumber,
-		"highestSN", r.highestSN,
-		"sn", rtph.SequenceNumber,
-		"startSN", r.extStartSN,
-		"lost", r.packetsLost,
-		"highestTS", r.highestTS,
-		"ts", rtph.Timestamp,
-		"tsDiff", rtph.Timestamp-r.highestTS,
-		"highestTime", r.highestTime,
-		"now", packetTime,
-		"timeDiff(ms)", float64(packetTime-r.highestTime)/1e6,
-	)
-	// LK-DEBUG-REMOVE END
 	// NOTE: current sequence number is counted as loss as it will be deducted in the duplicate check
 	r.packetsLost += uint32(uint16(r.extStartSN) - rtph.SequenceNumber)
 	r.extStartSN = uint32(rtph.SequenceNumber)
-	r.logger.Debugw("RTPSTATS_DEBUG, setting extStartSN moving back", "extStartSN", r.extStartSN) // LK-DEBUG-REMOVE
 }
 
 func (r *RTPStats) GetTotalPacketsPrimary() uint32 {
diff --git a/pkg/sfu/downtrack.go b/pkg/sfu/downtrack.go
index 4dd76b42a..11e98aeae 100644
--- a/pkg/sfu/downtrack.go
+++ b/pkg/sfu/downtrack.go
@@ -411,6 +411,8 @@ func (d *DownTrack) WriteRTP(extPkt *buffer.ExtPacket, layer int32) error {
 			if locked {
 				d.stopKeyFrameRequester()
 			}
+
+			d.logger.Debugw("forwarding key frame", "layer", layer)
 		}
 
 		d.rtpStats.Update(hdr, len(payload), 0, time.Now().UnixNano())
@@ -935,6 +937,7 @@ func (d *DownTrack) handleRTCP(bytes []byte) {
 		if pliOnce {
 			targetLayers := d.forwarder.TargetLayers()
 			if targetLayers != InvalidLayers {
+				d.logger.Debugw("sending PLI RTCP", "layer", targetLayers.spatial)
 				d.receiver.SendPLI(targetLayers.spatial)
 				d.isNACKThrottled.Store(true)
 				d.rtpStats.UpdatePliTime()
diff --git a/pkg/sfu/testutils/data.go b/pkg/sfu/testutils/data.go
index cd96469e5..8c65f6dd9 100644
--- a/pkg/sfu/testutils/data.go
+++ b/pkg/sfu/testutils/data.go
@@ -11,7 +11,6 @@ import (
 
 type TestExtPacketParams struct {
 	SetMarker      bool
-	SetPadding     bool
 	IsHead         bool
 	IsKeyFrame     bool
 	PayloadType    uint8
@@ -19,7 +18,7 @@ type TestExtPacketParams struct {
 	Timestamp      uint32
 	SSRC           uint32
 	PayloadSize    int
-	PaddingSize    int
+	PaddingSize    byte
 	ArrivalTime    int64
 }
 
@@ -29,15 +28,15 @@ func GetTestExtPacket(params *TestExtPacketParams) (*buffer.ExtPacket, error) {
 	packet := rtp.Packet{
 		Header: rtp.Header{
 			Version:        2,
-			Padding:        params.SetPadding,
+			Padding:        params.PaddingSize != 0,
 			Marker:         params.SetMarker,
 			PayloadType:    params.PayloadType,
 			SequenceNumber: params.SequenceNumber,
 			Timestamp:      params.Timestamp,
 			SSRC:           params.SSRC,
 		},
-		Payload: make([]byte, params.PayloadSize),
-		// LK-TODO need a newer version of pion/rtp PaddingSize: params.PaddingSize,
+		Payload:     make([]byte, params.PayloadSize),
+		PaddingSize: params.PaddingSize,
 	}
 
 	raw, err := packet.Marshal()