webrtcbin: ICE connection takes ~2 seconds to move from checking to connected
I'm trying to narrow down why our WebRTC connections take ~2 seconds to complete however I'm coming up short. Running GStreamer 1.20.3
We have implemented a GStreamer pipeline in Python with a coturn server set as the WebRTC TURN server. From our logs (as below - logging on element state change), we can see it takes about ~2 seconds from getting the answer from janus to the connection completing. Essentially the exact same config on the browser, which connects almost instantaneously.
Any pointers as to what I can look into and why this takes a while to complete? We don't do trickle ice, we wait for all candidates to be gathered before sending the offer, and then the answer contains all candidates too. You can see that the candidates are gathered super quick, but after going into the CHECKING connection state, it takes 2s before the funnel is then set up and the pipeline continues
2022-09-14 13:11:17,574 - src.elements.webrtc - INFO - Gathering ICE...
2022-09-14 13:11:17,665 - src.elements.webrtc - INFO - Got Ice Candidate candidate:25 1 UDP 337641727 172.18.0.20 54167 typ relay raddr 10.1.1.77 rport 9
2022-09-14 13:11:17,738 - src.elements.webrtc - INFO - Gathering ICE Complete
2022-09-14 13:11:17,738 - src.elements.webrtc - INFO - Sending offer after gathering ICE
2022-09-14 13:11:17,739 - src.signalling - INFO - Sending offer
2022-09-14 13:11:17,739 - socketio.client - INFO - Emitting event "transcoder:streamEvent" [/]
2022-09-14 13:11:17,740 - engineio.client - INFO - Sending packet MESSAGE data 2["transcoder:streamEvent",{"jsep":{"type":"offer","sdp":"v=0\r\no=- 5447281297030345240 0 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=ice-options:trickle\r\na=group:BUNDLE video0\r\nm=video 9 UDP/TLS/RTP/SAVPF 96 97 98 99 100\r\nc=IN IP4 0.0.0.0\r\na=setup:actpass\r\na=ice-ufrag:DkyQDFCOwnanmALqDGJ9+pWuprNayvcs\r\na=ice-pwd:HbDlmlqEdVQd72Ke7YBTP0mpDPQvttQu\r\na=rtcp-mux\r\na=rtcp-rsize\r\na=sendonly\r\na=rtpmap:96 H264/90000\r\na=rtcp-fb:96 nack\r\na=rtcp-fb:96 nack pli\r\na=rtcp-fb:96 transport-cc\r\na=framerate:25\r\na=fmtp:96 packetization-mode=1;sprop-parameter-sets=Z00AKZpnA8ARPy4C3AQEBQAAAwPoAADDUOhgAP78AAP75rvLjQwAH9+AAH9813lwoA==,aO48gA==;profile-level-id=4d0029;level-asymmetry-allowed=1\r\na=rtpmap:97 red/90000\r\na=rtpmap:98 ulpfec/90000\r\na=rtpmap:99 rtx/90000\r\na=fmtp:99 apt=97\r\na=rtpmap:100 rtx/90000\r\na=fmtp:100 apt=96\r\na=ssrc-group:FID 550766102 480361981\r\na=ssrc:550766102 msid:user3017390952@host-f37ba75a webrtctransceiver0\r\na=ssrc:550766102 cname:user3017390952@host-f37ba75a\r\na=ssrc:480361981 msid:user3017390952@host-f37ba75a webrtctransceiver0\r\na=ssrc:480361981 cname:user3017390952@host-f37ba75a\r\na=mid:video0\r\na=fingerprint:sha-256 68:E6:29:0C:B1:31:CE:DA:45:BB:9B:B3:38:2D:9D:FE:F7:AD:82:C4:58:4E:64:AA:91:9E:FC:3A:4C:05:6C:C6\r\na=rtcp-mux-only\r\na=candidate:25 1 UDP 337641727 172.18.0.20 54167 typ relay raddr 10.1.1.77 rport 9\r\n","trickle":false},"streamId":"0583e567874945a3bd816f77aa5adcd8","type":"streamOffer"}]
2022-09-14 13:11:17,817 - engineio.client - INFO - Received packet MESSAGE data 2["transcoder:streamAnswer",{"handleId":4298755108933040,"jsep":{"type":"answer","sdp":"v=0\r\no=- 1663117877744549 1 IN IP4 172.18.0.19\r\ns=VideoRoom 0583e567874945a3bd816f77aa5adcd8\r\nt=0 0\r\na=group:BUNDLE video0\r\na=ice-options:trickle\r\na=fingerprint:sha-256 E0:20:FB:D3:48:87:91:C9:90:C4:97:51:BE:9C:9A:DA:4B:5E:4C:0D:1E:96:29:7B:B2:76:C8:0F:01:EF:88:B0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS janus\r\nm=video 9 UDP/TLS/RTP/SAVPF 96 100\r\nc=IN IP4 172.18.0.19\r\na=recvonly\r\na=mid:video0\r\na=rtcp-mux\r\na=ice-ufrag:M/y0\r\na=ice-pwd:4V2R0b3bbDo7TVfXw5J8dv\r\na=ice-options:trickle\r\na=setup:active\r\na=rtpmap:96 H264/90000\r\na=rtcp-fb:96 ccm fir\r\na=rtcp-fb:96 nack\r\na=rtcp-fb:96 nack pli\r\na=rtcp-fb:96 goog-remb\r\na=rtcp-fb:96 transport-cc\r\na=fmtp:96 packetization-mode=1;sprop-parameter-sets=Z00AKZpnA8ARPy4C3AQEBQAAAwPoAADDUOhgAP78AAP75rvLjQwAH9+AAH9813lwoA==,aO48gA==;profile-level-id=4d0029;level-asymmetry-allowed=1\r\na=rtpmap:100 rtx/90000\r\na=fmtp:100 apt=96\r\na=msid:janus janusvideo0\r\na=ssrc:2150183323 cname:janus\r\na=ssrc:2520873591 cname:janus\r\na=candidate:1 1 udp 2015363327 172.18.0.19 39961 typ host\r\na=candidate:1 1 udp 2015363327 172.18.0.19 39961 typ host\r\na=candidate:1 1 udp 2015363327 1.1.1.1 39961 typ host\r\na=end-of-candidates\r\n"},"server":"development","sessionId":6249999229949083,"streamId":"0583e567874945a3bd816f77aa5adcd8"}]
2022-09-14 13:11:17,818 - socketio.client - INFO - Received event "transcoder:streamAnswer" [/]
2022-09-14 13:11:17,818 - src.signalling - INFO - Received answer
2022-09-14 13:11:17,819 - src.elements.webrtc - DEBUG - Received answer:
{'handleId': 4298755108933040, 'jsep': {'type': 'answer', 'sdp': 'v=0\r\no=- 1663117877744549 1 IN IP4 172.18.0.19\r\ns=VideoRoom 0583e567874945a3bd816f77aa5adcd8\r\nt=0 0\r\na=group:BUNDLE video0\r\na=ice-options:trickle\r\na=fingerprint:sha-256 E0:20:FB:D3:48:87:91:C9:90:C4:97:51:BE:9C:9A:DA:4B:5E:4C:0D:1E:96:29:7B:B2:76:C8:0F:01:EF:88:B0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS janus\r\nm=video 9 UDP/TLS/RTP/SAVPF 96 100\r\nc=IN IP4 172.18.0.19\r\na=recvonly\r\na=mid:video0\r\na=rtcp-mux\r\na=ice-ufrag:M/y0\r\na=ice-pwd:4V2R0b3bbDo7TVfXw5J8dv\r\na=ice-options:trickle\r\na=setup:active\r\na=rtpmap:96 H264/90000\r\na=rtcp-fb:96 ccm fir\r\na=rtcp-fb:96 nack\r\na=rtcp-fb:96 nack pli\r\na=rtcp-fb:96 goog-remb\r\na=rtcp-fb:96 transport-cc\r\na=fmtp:96 packetization-mode=1;sprop-parameter-sets=Z00AKZpnA8ARPy4C3AQEBQAAAwPoAADDUOhgAP78AAP75rvLjQwAH9+AAH9813lwoA==,aO48gA==;profile-level-id=4d0029;level-asymmetry-allowed=1\r\na=rtpmap:100 rtx/90000\r\na=fmtp:100 apt=96\r\na=msid:janus janusvideo0\r\na=ssrc:2150183323 cname:janus\r\na=ssrc:2520873591 cname:janus\r\na=candidate:1 1 udp 2015363327 172.18.0.19 39961 typ host\r\na=candidate:1 1 udp 2015363327 172.18.0.19 39961 typ host\r\na=candidate:1 1 udp 2015363327 1.1.1.1 39961 typ host\r\na=end-of-candidates\r\n'}, 'server': 'development', 'sessionId': 6249999229949083, 'streamId': '0583e567874945a3bd816f77aa5adcd8'}
2022-09-14 13:11:17,819 - src.elements.webrtc - INFO - Setting up sessionId keepalive for 6249999229949083
2022-09-14 13:11:17,828 - src.app - DEBUG - Element rtpfunnel0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:17,828 - src.app - DEBUG - Element rtpfunnel0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:17,829 - src.app - DEBUG - Element rtpfunnel0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:17,829 - src.app - DEBUG - Element queue3 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:17,830 - src.app - DEBUG - (type=<enum GST_STREAM_STATUS_TYPE_CREATE of type Gst.StreamStatusType>, owner=<__gi__.GstQueue object at 0x7f88ecf98240 (GstQueue at 0x7f88d018c9d0)>)
2022-09-14 13:11:17,830 - src.app - DEBUG - (type=<enum GST_STREAM_STATUS_TYPE_ENTER of type Gst.StreamStatusType>, owner=<__gi__.GstQueue object at 0x7f88ecf98240 (GstQueue at 0x7f88d018c9d0)>)
2022-09-14 13:11:17,831 - src.app - DEBUG - Element queue3 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:17,831 - src.app - DEBUG - Element queue3 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:17,832 - src.app - DEBUG - Element rtprtxsend0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:17,833 - src.app - DEBUG - Element bin0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:17,834 - src.app - DEBUG - (type=<enum GST_STREAM_STATUS_TYPE_CREATE of type Gst.StreamStatusType>, owner=<__gi__.GstRtpRtxSend object at 0x7f88ecfdfdc0 (GstRtpRtxSend at 0x7f88dc186000)>)
2022-09-14 13:11:17,834 - src.app - DEBUG - Element rtprtxsend0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:17,835 - src.app - DEBUG - Element bin0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:17,836 - src.app - DEBUG - Element rtprtxsend0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:17,838 - src.app - DEBUG - Element bin0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:17,838 - src.app - DEBUG - Element clocksync0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:17,839 - src.app - DEBUG - Element clocksync0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:17,839 - src.app - DEBUG - Element clocksync0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:17,840 - src.elements.webrtc - DEBUG - WebRTC State is <enum GST_WEBRTC_PEER_CONNECTION_STATE_CONNECTING of type GstWebRTC.WebRTCPeerConnectionState>
2022-09-14 13:11:17,840 - src.elements.webrtc - DEBUG - WebRTC ICE State is <enum GST_WEBRTC_ICE_CONNECTION_STATE_CHECKING of type GstWebRTC.WebRTCICEConnectionState>
2022-09-14 13:11:17,841 - src.app - DEBUG - (type=<enum GST_STREAM_STATUS_TYPE_ENTER of type Gst.StreamStatusType>, owner=<__gi__.GstRtpRtxSend object at 0x7f88ecfbbbc0 (GstRtpRtxSend at 0x7f88dc186000)>)
2022-09-14 13:11:19,925 - src.app - DEBUG - Element funnel0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:19,927 - src.app - DEBUG - Element dtlsenc0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:19,928 - src.app - DEBUG - Element clocksync_0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:19,930 - src.app - DEBUG - Element srtpenc0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:19,931 - src.app - DEBUG - Element dtlssrtpenc0 going from GST_STATE_NULL to GST_STATE_READY
2022-09-14 13:11:19,932 - src.app - DEBUG - Element funnel0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:19,933 - src.app - DEBUG - (type=<enum GST_STREAM_STATUS_TYPE_CREATE of type Gst.StreamStatusType>, owner=<__gi__.GstDtlsEnc object at 0x7f88ffa2a980 (GstDtlsEnc at 0x7f88e82a7600)>)
2022-09-14 13:11:19,934 - src.app - DEBUG - Element dtlsenc0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:19,934 - src.app - DEBUG - Element clocksync_0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:19,935 - src.app - DEBUG - Element srtpenc0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:19,936 - src.app - DEBUG - (type=<enum GST_STREAM_STATUS_TYPE_ENTER of type Gst.StreamStatusType>, owner=<__gi__.GstDtlsEnc object at 0x7f88ecfee540 (GstDtlsEnc at 0x7f88e82a7600)>)
2022-09-14 13:11:19,936 - src.app - DEBUG - Element dtlssrtpenc0 going from GST_STATE_READY to GST_STATE_PAUSED
2022-09-14 13:11:19,937 - src.app - DEBUG - Element funnel0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:19,938 - src.app - DEBUG - Element dtlsenc0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:19,939 - src.app - DEBUG - Element clocksync_0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:19,939 - src.app - DEBUG - Element srtpenc0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:19,940 - src.app - DEBUG - Element dtlssrtpenc0 going from GST_STATE_PAUSED to GST_STATE_PLAYING
2022-09-14 13:11:19,941 - src.app - DEBUG - <flags GST_MESSAGE_STREAM_START of type Gst.MessageType>, <Gst.Pipeline object at 0x7f88ff83b540 (GstPipeline at 0x7f88e8008130)>
2022-09-14 13:11:19,941 - src.app - DEBUG - <flags GST_MESSAGE_LATENCY of type Gst.MessageType>, <__gi__.GstNiceSink object at 0x7f88ecfee540 (GstNiceSink at 0x7f88dc0d91c0)>
2022-09-14 13:11:19,976 - src.elements.webrtc - DEBUG - WebRTC State is <enum GST_WEBRTC_PEER_CONNECTION_STATE_CONNECTED of type GstWebRTC.WebRTCPeerConnectionState>
2022-09-14 13:11:19,976 - src.elements.webrtc - DEBUG - WebRTC ICE State is <enum GST_WEBRTC_ICE_CONNECTION_STATE_COMPLETED of type GstWebRTC.WebRTCICEConnectionState>
Any pointers or things I should be looking at? More than happy to open any MR's if we find a bug, I just need to know where to look