From bd5382daaad358e46537ea932a0c1675cb0ff4fa Mon Sep 17 00:00:00 2001 From: Raja Subramanian Date: Thu, 27 Nov 2025 10:02:01 +0530 Subject: [PATCH] Splitting transport close timeout logs. (#4108) After adding more fields in https://github.com/livekit/livekit/pull/4105/files, it was not even logging. Access to one of the added fields must have ended up waiting on a lock and blocked. Unfotunately, the deadlock fix in https://github.com/pion/ice/pull/840 did not address the peer connection close hang. Splitting the logs so that the base log still happens. Ordering after looking at the code and guessing what could still log to see if we get more of the logs and learn more about the state and which lock ends up the first blocking one. --- pkg/rtc/transport.go | 61 ++++++++++++++++++++++++++++++++------------ 1 file changed, 44 insertions(+), 17 deletions(-) diff --git a/pkg/rtc/transport.go b/pkg/rtc/transport.go index 23f88e15e..63197745a 100644 --- a/pkg/rtc/transport.go +++ b/pkg/rtc/transport.go @@ -192,10 +192,12 @@ type trackDescription struct { // PCTransport is a wrapper around PeerConnection, with some helper methods type PCTransport struct { - params TransportParams - pc *webrtc.PeerConnection - iceTransport *webrtc.ICETransport - me *webrtc.MediaEngine + params TransportParams + pc *webrtc.PeerConnection + sctpTransport *webrtc.SCTPTransport // CLOSE-DEBUG-CLEANUP + dtlsTransport *webrtc.DTLSTransport // CLOSE-DEBUG-CLEANUP + iceTransport *webrtc.ICETransport + me *webrtc.MediaEngine lock sync.RWMutex @@ -594,6 +596,8 @@ func (t *PCTransport) createPeerConnection() (cc.BandwidthEstimator, error) { t.pc.OnDataChannel(t.onDataChannel) t.pc.OnTrack(t.params.Handler.OnTrack) + t.sctpTransport = t.pc.SCTP() + t.dtlsTransport = t.sctpTransport.Transport() t.iceTransport = t.pc.SCTP().Transport().ICETransport() if t.iceTransport == nil { return bwe, ErrNoICETransport @@ -1465,16 +1469,6 @@ func (t *PCTransport) Close() { iceStats := t.mayFailedICEStats t.lock.Unlock() - numActiveTransceivers := 0 - numInactiveTransceivers := 0 - for _, tr := range t.pc.GetTransceivers() { - if tr.Direction() == webrtc.RTPTransceiverDirectionInactive { - numInactiveTransceivers++ - } else { - numActiveTransceivers++ - } - } - t.params.Logger.Infow( "transport close timeout", "eventsQueueDone", eventsQueueDone.Load(), @@ -1490,16 +1484,49 @@ func (t *PCTransport) Close() { "iceConnectionState", t.iceConnectionState.Load().(webrtc.ICEConnectionState).String(), "icceConnectionStateChangedAt", t.iceConnectionStateChangeAt.Load(), "peerConnectionState", t.peerConnectionState.Load().(webrtc.PeerConnectionState).String(), - "signalingState", t.pc.SignalingState().String(), "iceStats", iceCandidatePairStatsEncoder{iceStats}, "iceConnectionInfo", t.GetICEConnectionInfo(), "connectionType", t.connectionDetails.GetConnectionType(), - "sctpTransportState", t.pc.SCTP().State().String(), - "dltsTransportState", t.pc.SCTP().Transport().State().String(), + ) + + t.params.Logger.Infow( + "transport close timeout - signalling state", + "signalingState", t.pc.SignalingState().String(), + ) + + t.params.Logger.Infow( + "transport close timeout - iceTransport state", "iceTransportState", t.iceTransport.State().String(), + ) + + if t.sctpTransport != nil { + t.params.Logger.Infow( + "transport close timeout - sctpTransport state", + "sctpTransportState", t.sctpTransport.State().String(), + ) + } + + numActiveTransceivers := 0 + numInactiveTransceivers := 0 + for _, tr := range t.pc.GetTransceivers() { + if tr.Direction() == webrtc.RTPTransceiverDirectionInactive { + numInactiveTransceivers++ + } else { + numActiveTransceivers++ + } + } + t.params.Logger.Infow( + "transport close timeout - transceivers state", "numInactiveTransceivers", numInactiveTransceivers, "numActiveTransceivers", numActiveTransceivers, ) + + if t.dtlsTransport != nil { + t.params.Logger.Infow( + "transport close timeout - dtlsTransport state", + "dltsTransportState", t.dtlsTransport.State().String(), + ) + } } })