Add ice candidates logs for failed peerconnection (#3473)

This commit is contained in:
cnderrauber
2025-02-27 14:47:28 +08:00
committed by GitHub
parent 83a839811c
commit 900da73e6d
3 changed files with 118 additions and 8 deletions

4
go.mod
View File

@@ -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

8
go.sum
View File

@@ -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=

View File

@@ -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
}