Log correct time difference (#2192)

pkg/sfu/buffer/rtpstats_sender.go

@@ -541,12 +541,16 @@ func (r *RTPStatsSender) UpdateFromReceiverReport(rr rtcp.ReceptionReport) (rtt
 		eis := &s.intervalStats
 		eis.aggregate(&is)
 		if is.packetsNotFound != 0 {
+			timeSinceLastRR := time.Since(r.lastRRTime)
+			if r.lastRRTime.IsZero() {
+				timeSinceLastRR = time.Since(r.startTime)
+			}
 			if r.metadataCacheOverflowCount%10 == 0 {
 				r.logger.Infow(
 					"metadata cache overflow",
 					"lastRRTime", r.lastRRTime.String(),
 					"lastRR", r.lastRR,
-					"sinceLastRR", time.Since(r.lastRRTime).String(),
+					"timeSinceLastRR", timeSinceLastRR.String(),
 					"receivedRR", rr,
 					"extStartSN", r.extStartSN,
 					"extHighestSN", r.extHighestSN,
@@ -636,10 +640,10 @@ func (r *RTPStatsSender) GetRtcpSenderReport(ssrc uint32, calculatedClockRate ui
 		At:              now,
 	}
 	if r.srNewest != nil {
-		timeSinceLastReport := nowNTP.Time().Sub(r.srNewest.NTPTimestamp.Time()).Seconds()
+		timeSinceLastReport := nowNTP.Time().Sub(r.srNewest.NTPTimestamp.Time())
 		rtpDiffSinceLastReport := nowRTPExt - r.srNewest.RTPTimestampExt
-		windowClockRate := float64(rtpDiffSinceLastReport) / timeSinceLastReport
-		if timeSinceLastReport > 0.2 && math.Abs(float64(r.params.ClockRate)-windowClockRate) > 0.2*float64(r.params.ClockRate) {
+		windowClockRate := float64(rtpDiffSinceLastReport) / timeSinceLastReport.Seconds()
+		if timeSinceLastReport.Seconds() > 0.2 && math.Abs(float64(r.params.ClockRate)-windowClockRate) > 0.2*float64(r.params.ClockRate) {
 			if r.clockSkewCount%10 == 0 {
 				r.logger.Infow(
 					"sending sender report, clock skew",
@@ -655,7 +659,7 @@ func (r *RTPStatsSender) GetRtcpSenderReport(ssrc uint32, calculatedClockRate ui
 					"nowRTPExtUsingTime", nowRTPExtUsingTime,
 					"calculatedClockRate", calculatedClockRate,
 					"nowRTPExtUsingRate", nowRTPExtUsingRate,
-					"timeSinceLastReport", timeSinceLastReport,
+					"timeSinceLastReport", timeSinceLastReport.String(),
 					"rtpDiffSinceLastReport", rtpDiffSinceLastReport,
 					"windowClockRate", windowClockRate,
 					"count", r.clockSkewCount,

pkg/sfu/videolayerselector/dependencydescriptor.go

@@ -63,7 +63,7 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r
 	ddwdt := extPkt.DependencyDescriptor
 	if ddwdt == nil {
 		// packet doesn't have dependency descriptor
-		d.logger.Debugw(fmt.Sprintf("drop packet, no DD, incoming %v", extPkt.VideoLayer))
+		d.logger.Debugw(fmt.Sprintf("drop packet, no DD, incoming %v, sn: %d, isKeyFrame: %v", extPkt.VideoLayer, extPkt.Packet.SequenceNumber, extPkt.KeyFrame))
 		return
 	}
 
@@ -81,20 +81,22 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r
 	sd, err := d.decisions.GetDecision(extFrameNum)
 	if err != nil {
 		// do not mark as dropped as only error is an old frame
-		d.logger.Debugw(fmt.Sprintf("drop packet on decision error, incoming %v, fn: %d/%d",
+		d.logger.Debugw(fmt.Sprintf("drop packet on decision error, incoming %v, fn: %d/%d, sn: %d",
 			incomingLayer,
 			dd.FrameNumber,
 			extFrameNum,
+			extPkt.Packet.SequenceNumber,
 		), "err", err)
 		return
 	}
 	switch sd {
 	case selectorDecisionDropped:
 		// a packet of an alreadty dropped frame, maintain decision
-		d.logger.Debugw(fmt.Sprintf("drop packet already dropped, incoming %v, fn: %d/%d",
+		d.logger.Debugw(fmt.Sprintf("drop packet already dropped, incoming %v, fn: %d/%d, sm: %d",
 			incomingLayer,
 			dd.FrameNumber,
 			extFrameNum,
+			extPkt.Packet.SequenceNumber,
 		))
 		return
 	}
@@ -144,23 +146,34 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r
 
 	if highestDecodeTarget.Target < 0 {
 		// no active decode target, do not select
-		d.logger.Debugw(fmt.Sprintf("drop packet for no target found, decodeTargets %v, tagetLayer %v, incoming %v",
-			d.decodeTargets,
-			d.targetLayer,
-			incomingLayer,
-		))
+		d.logger.Debugw(
+			"drop packet for no target found",
+			"highestDecodeTarget", highestDecodeTarget,
+			"decodeTargets", d.decodeTargets,
+			"tagetLayer", d.targetLayer,
+			"incoming", incomingLayer,
+			"fn", dd.FrameNumber,
+			"efn", extFrameNum,
+			"sn", extPkt.Packet.SequenceNumber,
+			"isKeyFrame", extPkt.KeyFrame,
+		)
 		d.decisions.AddDropped(extFrameNum)
 		return
 	}
 
 	// DD-TODO : if bandwidth in congest, could drop the 'Discardable' frame
 	if dti == dede.DecodeTargetNotPresent {
-		d.logger.Debugw(fmt.Sprintf("drop packet for decode target not present, highestDecodeTarget %d, incoming %v, fn: %d/%d",
-			highestDecodeTarget,
-			incomingLayer,
-			dd.FrameNumber,
-			extFrameNum,
-		))
+		d.logger.Debugw(
+			"drop packet for decode target not present",
+			"highestDecodeTarget", highestDecodeTarget,
+			"decodeTargets", d.decodeTargets,
+			"tagetLayer", d.targetLayer,
+			"incoming", incomingLayer,
+			"fn", dd.FrameNumber,
+			"efn", extFrameNum,
+			"sn", extPkt.Packet.SequenceNumber,
+			"isKeyFrame", extPkt.KeyFrame,
+		)
 		d.decisions.AddDropped(extFrameNum)
 		return
 	}
@@ -180,12 +193,17 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r
 		}
 	}
 	if !isDecodable {
-		d.logger.Debugw(fmt.Sprintf("drop packet for not decodable, highestDecodeTarget %d, incoming %v, fn: %d/%d",
-			highestDecodeTarget,
-			incomingLayer,
-			dd.FrameNumber,
-			extFrameNum,
-		))
+		d.logger.Debugw(
+			"drop packet for not decodable",
+			"highestDecodeTarget", highestDecodeTarget,
+			"decodeTargets", d.decodeTargets,
+			"tagetLayer", d.targetLayer,
+			"incoming", incomingLayer,
+			"fn", dd.FrameNumber,
+			"efn", extFrameNum,
+			"sn", extPkt.Packet.SequenceNumber,
+			"isKeyFrame", extPkt.KeyFrame,
+		)
 		d.decisions.AddDropped(extFrameNum)
 		return
 	}
@@ -203,7 +221,10 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r
 				"req", d.requestSpatial,
 				"maxSeen", d.maxSeenLayer,
 				"feed", extPkt.Packet.SSRC,
-				"frame", extFrameNum,
+				"fn", dd.FrameNumber,
+				"efn", extFrameNum,
+				"sn", extPkt.Packet.SequenceNumber,
+				"isKeyFrame", extPkt.KeyFrame,
 			)
 		}
 
@@ -212,7 +233,16 @@ func (d *DependencyDescriptor) Select(extPkt *buffer.ExtPacket, _layer int32) (r
 
 		d.previousActiveDecodeTargetsBitmask = d.activeDecodeTargetsBitmask
 		d.activeDecodeTargetsBitmask = buffer.GetActiveDecodeTargetBitmask(d.currentLayer, ddwdt.DecodeTargets)
-		d.logger.Debugw("switch to target", "highest", highestDecodeTarget.Layer, "current", d.currentLayer, "bitmask", *d.activeDecodeTargetsBitmask, "frame", extFrameNum)
+		d.logger.Debugw(
+			"switch to target",
+			"highestDecodeTarget", highestDecodeTarget,
+			"current", d.currentLayer,
+			"bitmask", *d.activeDecodeTargetsBitmask,
+			"fn", dd.FrameNumber,
+			"efn", extFrameNum,
+			"sn", extPkt.Packet.SequenceNumber,
+			"isKeyFrame", extPkt.KeyFrame,
+		)
 	}
 
 	ddExtension := &dede.DependencyDescriptorExtension{

pkg/sfu/videolayerselector/dependencydescriptor_test.go

@@ -137,7 +137,7 @@ func TestDependencyDescriptor(t *testing.T) {
 	ddSelector.SetRequestSpatial(1)
 
 	// no dd ext, dropped
-	ret := ddSelector.Select(&buffer.ExtPacket{}, 0)
+	ret := ddSelector.Select(&buffer.ExtPacket{Packet: &rtp.Packet{}}, 0)
 	require.False(t, ret.IsSelected)
 	require.True(t, ret.IsRelevant)
 
@@ -153,6 +153,7 @@ func TestDependencyDescriptor(t *testing.T) {
 				},
 			},
 		},
+		Packet: &rtp.Packet{},
 	}, 0)
 	require.False(t, ret.IsSelected)
 	require.True(t, ret.IsRelevant)