From 96cb829b84fc848b0cf98932eaa20ba91013d25b Mon Sep 17 00:00:00 2001 From: Raja Subramanian Date: Thu, 23 May 2024 13:03:26 +0530 Subject: [PATCH] Log more info when adjusting start timestamp. (#2722) Seeing some large time stamp jump in relay down track once in a while. Logging more details on time stamp switch to learn more. --- pkg/sfu/buffer/rtpstats_receiver.go | 66 ++++++++------------- pkg/sfu/buffer/rtpstats_sender.go | 91 +++++++++++++---------------- 2 files changed, 65 insertions(+), 92 deletions(-) diff --git a/pkg/sfu/buffer/rtpstats_receiver.go b/pkg/sfu/buffer/rtpstats_receiver.go index da387dc44..9ffc2507e 100644 --- a/pkg/sfu/buffer/rtpstats_receiver.go +++ b/pkg/sfu/buffer/rtpstats_receiver.go @@ -169,27 +169,32 @@ func (r *RTPStatsReceiver) Update( pktSize := uint64(hdrSize + payloadSize + paddingSize) gapSN := int64(resSN.ExtendedVal - resSN.PreExtendedHighest) + getLoggingFields := func() []interface{} { + return []interface{}{ + "extStartSN", r.sequenceNumber.GetExtendedStart(), + "extHighestSN", r.sequenceNumber.GetExtendedHighest(), + "extStartTS", r.timestamp.GetExtendedStart(), + "extHighestTS", r.timestamp.GetExtendedHighest(), + "firstTime", r.firstTime.String(), + "highestTime", r.highestTime.String(), + "prevSN", resSN.PreExtendedHighest, + "currSN", resSN.ExtendedVal, + "gapSN", gapSN, + "prevTS", resTS.PreExtendedHighest, + "currTS", resTS.ExtendedVal, + "gapTS", resTS.ExtendedVal - resTS.PreExtendedHighest, + "packetTime", packetTime.String(), + "sequenceNumber", sequenceNumber, + "timestamp", timestamp, + "marker", marker, + "hdrSize", hdrSize, + "payloadSize", payloadSize, + "paddingSize", paddingSize, + } + } if gapSN <= 0 { // duplicate OR out-of-order if -gapSN >= cNumSequenceNumbers/2 { - r.logger.Warnw( - "large sequence number gap negative", nil, - "extStartSN", r.sequenceNumber.GetExtendedStart(), - "extHighestSN", r.sequenceNumber.GetExtendedHighest(), - "extStartTS", r.timestamp.GetExtendedStart(), - "extHighestTS", r.timestamp.GetExtendedHighest(), - "firstTime", r.firstTime.String(), - "highestTime", r.highestTime.String(), - "prev", resSN.PreExtendedHighest, - "curr", resSN.ExtendedVal, - "gap", gapSN, - "packetTime", packetTime.String(), - "sequenceNumber", sequenceNumber, - "timestamp", timestamp, - "marker", marker, - "hdrSize", hdrSize, - "payloadSize", payloadSize, - "paddingSize", paddingSize, - ) + r.logger.Warnw("large sequence number gap negative", nil, getLoggingFields()...) } if gapSN != 0 { @@ -213,28 +218,7 @@ func (r *RTPStatsReceiver) Update( flowState.ExtTimestamp = resTS.ExtendedVal } else { // in-order if gapSN >= cNumSequenceNumbers/2 || resTS.ExtendedVal < resTS.PreExtendedHighest { - r.logger.Warnw( - "large sequence number gap OR time reversed", nil, - "extStartSN", r.sequenceNumber.GetExtendedStart(), - "extHighestSN", r.sequenceNumber.GetExtendedHighest(), - "extStartTS", r.timestamp.GetExtendedStart(), - "extHighestTS", r.timestamp.GetExtendedHighest(), - "firstTime", r.firstTime.String(), - "highestTime", r.highestTime.String(), - "prevSN", resSN.PreExtendedHighest, - "currSN", resSN.ExtendedVal, - "gapSN", gapSN, - "prevTS", resTS.PreExtendedHighest, - "currTS", resTS.ExtendedVal, - "gapTS", resTS.ExtendedVal-resTS.PreExtendedHighest, - "packetTime", packetTime.String(), - "sequenceNumber", sequenceNumber, - "timestamp", timestamp, - "marker", marker, - "hdrSize", hdrSize, - "payloadSize", payloadSize, - "paddingSize", paddingSize, - ) + r.logger.Warnw("large sequence number gap OR time reversed", nil, getLoggingFields()...) } // update gap histogram diff --git a/pkg/sfu/buffer/rtpstats_sender.go b/pkg/sfu/buffer/rtpstats_sender.go index 3074803d0..a46e4de07 100644 --- a/pkg/sfu/buffer/rtpstats_sender.go +++ b/pkg/sfu/buffer/rtpstats_sender.go @@ -284,33 +284,38 @@ func (r *RTPStatsSender) Update( pktSize := uint64(hdrSize + payloadSize + paddingSize) isDuplicate := false gapSN := int64(extSequenceNumber - r.extHighestSN) + getLoggingFields := func() []interface{} { + return []interface{}{ + "extStartSN", r.extStartSN, + "extHighestSN", r.extHighestSN, + "extStartTS", r.extStartTS, + "extHighestTS", r.extHighestTS, + "firstTime", r.firstTime.String(), + "highestTime", r.highestTime.String(), + "prevSN", r.extHighestSN, + "currSN", extSequenceNumber, + "gapSN", gapSN, + "prevTS", r.extHighestTS, + "currTS", extTimestamp, + "gapTS", extTimestamp - r.extHighestTS, + "packetTime", packetTime.String(), + "sequenceNumber", extSequenceNumber, + "timestamp", extTimestamp, + "marker", marker, + "hdrSize", hdrSize, + "payloadSize", payloadSize, + "paddingSize", paddingSize, + "firstSR", r.srFirst, + "lastSR", r.srNewest, + } + } if gapSN <= 0 { // duplicate OR out-of-order if payloadSize == 0 && extSequenceNumber < r.extStartSN { // do not start on a padding only packet return } if -gapSN >= cNumSequenceNumbers/2 { - r.logger.Warnw( - "large sequence number gap negative", nil, - "extStartSN", r.extStartSN, - "extHighestSN", r.extHighestSN, - "extStartTS", r.extStartTS, - "extHighestTS", r.extHighestTS, - "firstTime", r.firstTime.String(), - "highestTime", r.highestTime.String(), - "prev", r.extHighestSN, - "curr", extSequenceNumber, - "gap", gapSN, - "packetTime", packetTime.String(), - "sequenceNumber", extSequenceNumber, - "timestamp", extTimestamp, - "marker", marker, - "hdrSize", hdrSize, - "payloadSize", payloadSize, - "paddingSize", paddingSize, - "firstSR", r.srFirst, - "lastSR", r.srNewest, - ) + r.logger.Warnw("large sequence number gap negative", nil, getLoggingFields()...) } if extSequenceNumber < r.extStartSN { @@ -335,10 +340,12 @@ func (r *RTPStatsSender) Update( r.logger.Infow( "adjusting start sequence number", - "snBefore", r.extStartSN, - "snAfter", extSequenceNumber, - "tsBefore", r.extStartTS, - "tsAfter", extTimestamp, + append(getLoggingFields(), + "snBefore", r.extStartSN, + "snAfter", extSequenceNumber, + "tsBefore", r.extStartTS, + "tsAfter", extTimestamp, + )..., ) r.extStartSN = extSequenceNumber } @@ -357,28 +364,8 @@ func (r *RTPStatsSender) Update( r.setSnInfo(extSequenceNumber, r.extHighestSN, uint16(pktSize), uint8(hdrSize), uint16(payloadSize), marker, true) } } else { // in-order - if gapSN >= cNumSequenceNumbers/2 { - r.logger.Warnw( - "large sequence number gap", nil, - "extStartSN", r.extStartSN, - "extHighestSN", r.extHighestSN, - "extStartTS", r.extStartTS, - "extHighestTS", r.extHighestTS, - "firstTime", r.firstTime.String(), - "highestTime", r.highestTime.String(), - "prev", r.extHighestSN, - "curr", extSequenceNumber, - "gap", gapSN, - "packetTime", packetTime.String(), - "sequenceNumber", extSequenceNumber, - "timestamp", extTimestamp, - "marker", marker, - "hdrSize", hdrSize, - "payloadSize", payloadSize, - "paddingSize", paddingSize, - "firstSR", r.srFirst, - "lastSR", r.srNewest, - ) + if gapSN >= cNumSequenceNumbers/2 || extTimestamp < r.extHighestTS { + r.logger.Warnw("large sequence number gap OR time reversed", nil, getLoggingFields()...) } // update gap histogram @@ -396,10 +383,12 @@ func (r *RTPStatsSender) Update( if extTimestamp < r.extStartTS { r.logger.Infow( "adjusting start timestamp", - "snBefore", r.extStartSN, - "snAfter", extSequenceNumber, - "tsBefore", r.extStartTS, - "tsAfter", extTimestamp, + append(getLoggingFields(), + "snBefore", r.extStartSN, + "snAfter", extSequenceNumber, + "tsBefore", r.extStartTS, + "tsAfter", extTimestamp, + )..., ) r.extStartTS = extTimestamp }