diff --git a/go.mod b/go.mod index 1649c8258..8b2aa582c 100644 --- a/go.mod +++ b/go.mod @@ -33,7 +33,7 @@ require ( github.com/ory/dockertest/v3 v3.11.0 github.com/pion/datachannel v1.5.10 github.com/pion/dtls/v3 v3.0.4 - github.com/pion/ice/v4 v4.0.5 + github.com/pion/ice/v4 v4.0.7 github.com/pion/interceptor v0.1.37 github.com/pion/rtcp v1.2.15 github.com/pion/rtp v1.8.11 @@ -41,7 +41,7 @@ require ( github.com/pion/sdp/v3 v3.0.10 github.com/pion/transport/v3 v3.0.7 github.com/pion/turn/v4 v4.0.0 - github.com/pion/webrtc/v4 v4.0.8 + github.com/pion/webrtc/v4 v4.0.11 github.com/pkg/errors v0.9.1 github.com/prometheus/client_golang v1.20.5 github.com/redis/go-redis/v9 v9.7.0 diff --git a/go.sum b/go.sum index df97a7e09..b2cdd15ee 100644 --- a/go.sum +++ b/go.sum @@ -237,8 +237,8 @@ github.com/pion/datachannel v1.5.10 h1:ly0Q26K1i6ZkGf42W7D4hQYR90pZwzFOjTq5AuCKk github.com/pion/datachannel v1.5.10/go.mod h1:p/jJfC9arb29W7WrxyKbepTU20CFgyx5oLo8Rs4Py/M= github.com/pion/dtls/v3 v3.0.4 h1:44CZekewMzfrn9pmGrj5BNnTMDCFwr+6sLH+cCuLM7U= github.com/pion/dtls/v3 v3.0.4/go.mod h1:R373CsjxWqNPf6MEkfdy3aSe9niZvL/JaKlGeFphtMg= -github.com/pion/ice/v4 v4.0.5 h1:6awVfa1jg9YsI9/Lep4TG/o3kwS1Oayr5b8xz50ibJ8= -github.com/pion/ice/v4 v4.0.5/go.mod h1:JJaoEIxUIlGDA9gaRZbwXYqI3j6VG/QchpjX+QmwN6A= +github.com/pion/ice/v4 v4.0.7 h1:mnwuT3n3RE/9va41/9QJqN5+Bhc0H/x/ZyiVlWMw35M= +github.com/pion/ice/v4 v4.0.7/go.mod h1:y3M18aPhIxLlcO/4dn9X8LzLLSma84cx6emMSu14FGw= github.com/pion/interceptor v0.1.37 h1:aRA8Zpab/wE7/c0O3fh1PqY0AJI3fCSEM5lRWJVorwI= github.com/pion/interceptor v0.1.37/go.mod h1:JzxbJ4umVTlZAf+/utHzNesY8tmRkM2lVmkS82TTj8Y= github.com/pion/logging v0.2.3 h1:gHuf0zpoh1GW67Nr6Gj4cv5Z9ZscU7g/EaoC/Ke/igI= @@ -263,8 +263,8 @@ github.com/pion/transport/v3 v3.0.7 h1:iRbMH05BzSNwhILHoBoAPxoB9xQgOaJk+591KC9P1 github.com/pion/transport/v3 v3.0.7/go.mod h1:YleKiTZ4vqNxVwh77Z0zytYi7rXHl7j6uPLGhhz9rwo= github.com/pion/turn/v4 v4.0.0 h1:qxplo3Rxa9Yg1xXDxxH8xaqcyGUtbHYw4QSCvmFWvhM= github.com/pion/turn/v4 v4.0.0/go.mod h1:MuPDkm15nYSklKpN8vWJ9W2M0PlyQZqYt1McGuxG7mA= -github.com/pion/webrtc/v4 v4.0.8 h1:T1ZmnT9qxIJIt4d8XoiMOBrTClGHDDXNg9e/fh018Qc= -github.com/pion/webrtc/v4 v4.0.8/go.mod h1:HHBeUVBAC+j4ZFnYhovEFStF02Arb1EyD4G7e7HBTJw= +github.com/pion/webrtc/v4 v4.0.11 h1:0i7BNFH2n8LVp08q/dqM5iyZBXW4TITbD1+RwNqk/iY= +github.com/pion/webrtc/v4 v4.0.11/go.mod h1:C+5JA7KiyLyoKyGh7hVFD/HCAon3IB/tfniocpZ9JoU= github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= diff --git a/pkg/rtc/transport.go b/pkg/rtc/transport.go index 24e5801cb..89bac0e79 100644 --- a/pkg/rtc/transport.go +++ b/pkg/rtc/transport.go @@ -241,8 +241,10 @@ type PCTransport struct { currentOfferIceCredential string // ice user:pwd, for publish side ice restart checking pendingRestartIceOffer *webrtc.SessionDescription - connectionDetails *types.ICEConnectionDetails - selectedPair atomic.Pointer[webrtc.ICECandidatePair] + connectionDetails *types.ICEConnectionDetails + selectedPair atomic.Pointer[webrtc.ICECandidatePair] + mayFailedICEStats []iceCandidatePairStats + mayFailedICEStatsTimer *time.Timer } type TransportParams struct { @@ -573,6 +575,9 @@ func (t *PCTransport) setICEStartedAt(at time.Time) { if t.iceStartedAt.IsZero() { t.iceStartedAt = at + // checklist of ice agent will be cleared on ice failed, get stats before that + t.mayFailedICEStatsTimer = time.AfterFunc(iceFailedTimeoutTotal-time.Second, t.logMayFailedICEStats) + // set failure timer for tcp ice connection based on signaling RTT if t.preferTCP.Load() { signalingRTT := t.signalingRTT.Load() @@ -587,6 +592,7 @@ func (t *PCTransport) setICEStartedAt(at time.Time) { t.tcpICETimer = time.AfterFunc(tcpICETimeout, func() { if t.pc.ICEConnectionState() == webrtc.ICEConnectionStateChecking { t.params.Logger.Infow("TCP ICE connect timeout", "timeout", tcpICETimeout, "signalRTT", signalingRTT) + t.logMayFailedICEStats() t.handleConnectionFailed(true) } }) @@ -630,6 +636,43 @@ func (t *PCTransport) setICEConnectedAt(at time.Time) { t.tcpICETimer = nil } } + + if t.mayFailedICEStatsTimer != nil { + t.mayFailedICEStatsTimer.Stop() + t.mayFailedICEStatsTimer = nil + } + t.mayFailedICEStats = nil + t.lock.Unlock() +} + +func (t *PCTransport) logMayFailedICEStats() { + var candidatePairStats []webrtc.ICECandidatePairStats + pairStats := t.pc.GetStats() + candidateStats := make(map[string]webrtc.ICECandidateStats) + for _, stat := range pairStats { + switch stat := stat.(type) { + case webrtc.ICECandidatePairStats: + candidatePairStats = append(candidatePairStats, stat) + case webrtc.ICECandidateStats: + candidateStats[stat.ID] = stat + } + } + + iceStats := make([]iceCandidatePairStats, 0, len(candidatePairStats)) + for _, pairStat := range candidatePairStats { + iceStat := iceCandidatePairStats{ICECandidatePairStats: pairStat} + if local, ok := candidateStats[pairStat.LocalCandidateID]; ok { + iceStat.local = local + } + if remote, ok := candidateStats[pairStat.RemoteCandidateID]; ok { + remote.IP = MaybeTruncateIP(remote.IP) + iceStat.remote = remote + } + iceStats = append(iceStats, iceStat) + } + + t.lock.Lock() + t.mayFailedICEStats = iceStats t.lock.Unlock() } @@ -1078,7 +1121,13 @@ func (t *PCTransport) Close() { t.lossyDC.Close() t.lossyDC = nil } + + if t.mayFailedICEStatsTimer != nil { + t.mayFailedICEStatsTimer.Stop() + t.mayFailedICEStatsTimer = nil + } t.lock.Unlock() + t.outputAndClearICEStats() } func (t *PCTransport) clearConnTimer() { @@ -1951,6 +2000,10 @@ func (t *PCTransport) handleRemoteOfferReceived(sd *webrtc.SessionDescription) e t.resetShortConn() } + if offerRestartICE { + t.outputAndClearICEStats() + } + if err := t.setRemoteDescription(*sd); err != nil { return err } @@ -2018,6 +2071,7 @@ func (t *PCTransport) doICERestart() error { } if t.negotiationState == transport.NegotiationStateNone { + t.outputAndClearICEStats() return t.createAndSendOffer(&webrtc.OfferOptions{ICERestart: true}) } @@ -2049,6 +2103,7 @@ func (t *PCTransport) doICERestart() error { return errors.Wrap(err, "set remote description failed") } else { t.setNegotiationState(transport.NegotiationStateNone) + t.outputAndClearICEStats() return t.createAndSendOffer(&webrtc.OfferOptions{ICERestart: true}) } } @@ -2078,6 +2133,19 @@ func (t *PCTransport) onNegotiationFailed(warning bool, reason string) { t.params.Handler.OnNegotiationFailed() } +func (t *PCTransport) outputAndClearICEStats() { + t.lock.Lock() + stats := t.mayFailedICEStats + t.mayFailedICEStats = nil + t.lock.Unlock() + + if len(stats) > 0 { + t.params.Logger.Infow("ICE candidate pair stats", "stats", iceCandidatePairStatsEncoder{stats}) + } +} + +// ---------------------- + // configure subscriber transceiver for audio stereo and nack // pion doesn't support per transciver codec configuration, so the nack of this session will be disabled // forever once it is first disabled by a transceiver. @@ -2154,3 +2222,45 @@ func nonSimulcastRTXRepairsFromSDP(s *sdp.SessionDescription, logger logger.Logg return rtxRepairFlows } + +// ---------------------- + +type iceCandidatePairStatsEncoder struct { + stats []iceCandidatePairStats +} + +func (e iceCandidatePairStatsEncoder) MarshalLogArray(arr zapcore.ArrayEncoder) error { + for _, s := range e.stats { + if err := arr.AppendObject(s); err != nil { + return err + } + } + return nil +} + +type iceCandidatePairStats struct { + webrtc.ICECandidatePairStats + local, remote webrtc.ICECandidateStats +} + +func (r iceCandidatePairStats) MarshalLogObject(e zapcore.ObjectEncoder) error { + candidateToString := func(c webrtc.ICECandidateStats) string { + return fmt.Sprintf("%s:%d %s type(%s/%s), priority(%d)", c.IP, c.Port, c.Protocol, c.CandidateType, c.RelayProtocol, c.Priority) + } + e.AddString("state", string(r.State)) + e.AddBool("nominated", r.Nominated) + e.AddString("local", candidateToString(r.local)) + e.AddString("remote", candidateToString(r.remote)) + e.AddUint64("requestsSent", r.RequestsSent) + e.AddUint64("responsesReceived", r.ResponsesReceived) + e.AddUint64("requestsReceived", r.RequestsReceived) + e.AddUint64("responsesSent", r.ResponsesSent) + e.AddTime("firstRequestSentAt", r.FirstRequestTimestamp.Time()) + e.AddTime("lastRequestSentAt", r.LastRequestTimestamp.Time()) + e.AddTime("firstResponseReceivedAt", r.FirstResponseTimestamp.Time()) + e.AddTime("lastResponseReceivedAt", r.LastResponseTimestamp.Time()) + e.AddTime("firstRequestReceivedAt", r.FirstRequestReceivedTimestamp.Time()) + e.AddTime("lastRequestReceivedAt", r.LastRequestReceivedTimestamp.Time()) + + return nil +}