webrtc
webrtc copied to clipboard
pion
ICEConnectionState changes may be reported incorrectly
Your environment.
- Version: v3.1.60
- Browser: N/A
What did you do?
I have test which implements both sides of WebRTC connection, both using pion. ICE trickle is enabled, Test is executed on machine with multiple IP addresses.
What did you expect?
ICEConnectionState is set to checking first and then to connected. Latter state should persist.
What happened?
Usually ICE Connection State (both reported via OnICEConnectionStateChange callback and ICEConnectionState function) is set to checking and then to connected. However occasionally it is set to connected first and then to checking. Latter state persists for at least few seconds - my code calls ICEConnectionState every second and after few seconds it assumes that connection cannot be established.
Both state changes occurs in the same millisecond, what suggests that this may be some race condition. So far I saw failures only for side which creates offer.
I also have logs from pion itself. At the beginning I see "Setting new connection state: Checking", then some STUN logs, "The candidate (udp4 host x.x.x.x:46807, udp4 host x.x.x.x50577) is the best candidate available, marking it as nominated" somewhere in the middle and "Setting new connection state: Connected" close to the end - this looks good to me.
Sorry about that @sirzooro
That is coming from https://github.com/pion/ice
Would you be able to write a test/reproduce for this? This should be pretty easy to fix. I don't want it to regress though
I am trying to better understand this issue. I have analyzed more logs with similar case. I even found some when state changed to checking 10ms after connected state was set, so this may not be a race. I also found that this host-host pair actually is an exception in this case, usually it is host(local)-prflx(remote). If I understand logs correctly, STUN requests are received and processed before ICE candidates received via websocket were added. I suspect that in such case added host candidate does not replace matching prflx one and connection is not established immediately like for host-host pair.
I also found that sometimes when this happen pion is able to establish connection with host-prflx pair. What timeout is used by pion in such case? I suspect that timeout in my code is a bit too low and connection error is returned too early.
Edit: corresponding part of RFC 8838 for this case is here: https://www.rfc-editor.org/rfc/rfc8838#section-11-2.4.2.1
I did more testing today. This thing occurs randomly. On my dev VM I was not able to reproduce it. On another machine where tests are executed by pipeline it occurs about 3 times per 1000 connection attempts. I did not found any obvious pattern when this happen, beside receiving STUN request before adding ICE candidate what I mentioned above.
I found case when callbacks were called in proper order and with 7ms delay between then, but ICEConnectionState still was returning checking. Here are the logs:
00:47:05.179 DEBUG Sending Offer <SDP>
00:47:05.184 DEBUG Sending ICE candidate udp4 host 1.1.1.1:33911
00:47:05.195 DEBUG Received ICE candidate candidate:1029464733 1 udp 2130706431 1.1.1.1 48403 typ host
00:47:05.199 DEBUG Received ICE candidate candidate:3041112618 1 udp 2130706431 2.2.2.2 55981 typ host
00:47:05.206 DEBUG Sending ICE candidate udp4 host 2.2.2.2:43731
00:47:05.207 DEBUG Sending ICE candidate gather finished
00:47:05.211 DEBUG Received Answer <SDP>
00:47:05.227 INFO ICE Connection state changed to checking
00:47:05.228 DEBUG Selected candidate pair changed to (local) udp4 host 1.1.1.1:33911 <-> (remote) udp4 prflx 2.2.2.2:55981 related :0
00:47:05.235 INFO ICE Connection state changed to connected
ice TRACE: 00:47:05.179026 agent.go:585: Unset selected candidate pair
ice DEBUG: 00:47:05.183757 gather.go:178: GetConn by ufrag: XvIbgGRoAPoSDFLs
ice DEBUG: 00:47:05.204696 gather.go:178: GetConn by ufrag: XvIbgGRoAPoSDFLs
ice DEBUG: 00:47:05.214973 agent.go:468: Started agent: isControlling? true, remoteUfrag: "vlKuqRVoLzBDFyVh", remotePwd: "dQhGYjMDGtRIKtRaeiQHtmByqglMHgyS"
ice INFO: 2023/09/15 00:47:05 Setting new connection state: Checking
ice TRACE: 00:47:05.215193 agent.go:608: pinging all candidates
ice WARNING: 2023/09/15 00:47:05 pingAllCandidates called with no candidate pairs. Connection is not possible yet.
ice DEBUG: 00:47:05.215476 agent.go:1122: adding a new peer-reflexive candidate: 2.2.2.2:55981
ice TRACE: 00:47:05.215545 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 1.1.1.1:33911
ice DEBUG: 00:47:05.215745 agent.go:1122: adding a new peer-reflexive candidate: 1.1.1.1:48403
ice TRACE: 00:47:05.215794 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.215897 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.216002 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.216080 agent.go:608: pinging all candidates
ice TRACE: 00:47:05.216212 agent.go:976: ping STUN from udp4 host 1.1.1.1:33911 to udp4 prflx 2.2.2.2:55981 related :0
ice TRACE: 00:47:05.216279 agent.go:976: ping STUN from udp4 host 2.2.2.2:43731 to udp4 prflx 2.2.2.2:55981 related :0
ice TRACE: 00:47:05.216343 agent.go:976: ping STUN from udp4 host 1.1.1.1:33911 to udp4 prflx 1.1.1.1:48403 related :0
ice TRACE: 00:47:05.216414 agent.go:976: ping STUN from udp4 host 2.2.2.2:43731 to udp4 prflx 1.1.1.1:48403 related :0
ice TRACE: 00:47:05.216465 agent.go:608: pinging all candidates
ice TRACE: 00:47:05.216523 agent.go:976: ping STUN from udp4 host 1.1.1.1:33911 to udp4 prflx 2.2.2.2:55981 related :0
ice TRACE: 00:47:05.216615 agent.go:976: ping STUN from udp4 host 2.2.2.2:43731 to udp4 prflx 2.2.2.2:55981 related :0
ice TRACE: 00:47:05.216678 agent.go:976: ping STUN from udp4 host 1.1.1.1:33911 to udp4 prflx 1.1.1.1:48403 related :0
ice TRACE: 00:47:05.216742 agent.go:976: ping STUN from udp4 host 2.2.2.2:43731 to udp4 prflx 1.1.1.1:48403 related :0
ice TRACE: 00:47:05.219919 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 1.1.1.1:48403 related :0 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.219979 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 1.1.1.1:33911 <-> udp4 prflx 1.1.1.1:48403 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.220056 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.220169 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 1.1.1.1:48403 related :0 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.220215 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 1.1.1.1:33911 <-> udp4 prflx 1.1.1.1:48403 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.220285 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.220396 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 2.2.2.2:55981 related :0 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.220441 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 1.1.1.1:33911 <-> udp4 prflx 2.2.2.2:55981 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.220510 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.221187 selection.go:106: The candidate (udp4 host 1.1.1.1:33911, udp4 prflx 2.2.2.2:55981 related :0) is the best candidate available, marking it as nominated
ice TRACE: 00:47:05.221262 selection.go:87: ping STUN (nominate candidate pair) from udp4 host 1.1.1.1:33911 to udp4 prflx 2.2.2.2:55981 related :0
ice TRACE: 00:47:05.221301 agent.go:976: ping STUN from udp4 host 1.1.1.1:33911 to udp4 prflx 2.2.2.2:55981 related :0
ice TRACE: 00:47:05.221355 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.225878 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 2.2.2.2:55981 related :0 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.225955 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 1.1.1.1:33911 <-> udp4 prflx 2.2.2.2:55981 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.226043 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.226168 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 2.2.2.2:55981 related :0 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.226216 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 1.1.1.1:33911 <-> udp4 prflx 2.2.2.2:55981 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.226269 agent.go:591: Set selected candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 1.1.1.1:33911 <-> udp4 prflx 2.2.2.2:55981 related :0 (remote, prio 1862270975)
ice INFO: 2023/09/15 00:47:05 Setting new connection state: Connected
ice TRACE: 00:47:05.227765 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:05.227863 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228233 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 1.1.1.1:48403 related :0 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228286 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 2.2.2.2:43731 <-> udp4 prflx 1.1.1.1:48403 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.228361 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228471 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 1.1.1.1:48403 related :0 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228517 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 2.2.2.2:43731 <-> udp4 prflx 1.1.1.1:48403 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.228614 agent.go:1126: inbound STUN (Request) from 1.1.1.1:48403 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228728 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 2.2.2.2:55981 related :0 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228775 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 2.2.2.2:43731 <-> udp4 prflx 2.2.2.2:55981 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.228847 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228952 selection.go:130: inbound STUN (SuccessResponse) from udp4 prflx 2.2.2.2:55981 related :0 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.228997 selection.go:140: Found valid candidate pair: prio 7998392936314175488 (local, prio 2130706431) udp4 host 2.2.2.2:43731 <-> udp4 prflx 2.2.2.2:55981 related :0 (remote, prio 1862270975)
ice TRACE: 00:47:05.229069 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 2.2.2.2:43731
ice TRACE: 00:47:05.417658 selection.go:51: checking keepalive
ice TRACE: 00:47:07.418327 selection.go:51: checking keepalive
ice TRACE: 00:47:09.415969 agent.go:1126: inbound STUN (Request) from 2.2.2.2:55981 to udp4 host 1.1.1.1:33911
ice TRACE: 00:47:09.418446 selection.go:51: checking keepalive
00:47:11.183 WARN Still waiting for ICE connection: ICE not connected (checking)
I also have WebRTC connection stats:
{
"candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG": {
"candidateType": 3,
"deleted": false,
"id": "candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG",
"ip": "1.1.1.1",
"networkType": 1,
"port": 48403,
"priority": 1862270975,
"protocol": "udp",
"relayProtocol": "",
"timestamp": 1694738831184,
"transportId": "",
"type": "remote-candidate",
"url": ""
},
"candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr": {
"candidateType": 1,
"deleted": false,
"id": "candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr",
"ip": "2.2.2.2",
"networkType": 1,
"port": 43731,
"priority": 2130706431,
"protocol": "udp",
"relayProtocol": "",
"timestamp": 1694738831184,
"transportId": "",
"type": "local-candidate",
"url": ""
},
"candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr-candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG": {
"availableIncomingBitrate": 0,
"availableOutgoingBitrate": 0,
"bytesReceived": 0,
"bytesSent": 0,
"circuitBreakerTriggerCount": 0,
"consentExpiredTimestamp": -6795364578871,
"consentRequestsSent": 0,
"currentRoundTripTime": 0,
"firstRequestTimestamp": -6795364578871,
"id": "candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr-candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG",
"lastPacketReceivedTimestamp": -6795364578871,
"lastPacketSentTimestamp": -6795364578871,
"lastRequestTimestamp": -6795364578871,
"lastResponseTimestamp": -6795364578871,
"localCandidateId": "candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr",
"nominated": false,
"packetsReceived": 0,
"packetsSent": 0,
"remoteCandidateId": "candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG",
"requestsReceived": 0,
"requestsSent": 0,
"responsesReceived": 0,
"responsesSent": 0,
"retransmissionsReceived": 0,
"retransmissionsSent": 0,
"state": "succeeded",
"timestamp": 1694738831184,
"totalRoundTripTime": 0,
"transportId": "",
"type": "candidate-pair"
},
"candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr-candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor": {
"availableIncomingBitrate": 0,
"availableOutgoingBitrate": 0,
"bytesReceived": 0,
"bytesSent": 0,
"circuitBreakerTriggerCount": 0,
"consentExpiredTimestamp": -6795364578871,
"consentRequestsSent": 0,
"currentRoundTripTime": 0,
"firstRequestTimestamp": -6795364578871,
"id": "candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr-candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor",
"lastPacketReceivedTimestamp": -6795364578871,
"lastPacketSentTimestamp": -6795364578871,
"lastRequestTimestamp": -6795364578871,
"lastResponseTimestamp": -6795364578871,
"localCandidateId": "candidate:jH14fh5oAEgZgddaTgc3vbLtrHHTPOfr",
"nominated": false,
"packetsReceived": 0,
"packetsSent": 0,
"remoteCandidateId": "candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor",
"requestsReceived": 0,
"requestsSent": 0,
"responsesReceived": 0,
"responsesSent": 0,
"retransmissionsReceived": 0,
"retransmissionsSent": 0,
"state": "succeeded",
"timestamp": 1694738831184,
"totalRoundTripTime": 0,
"transportId": "",
"type": "candidate-pair"
},
"candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG": {
"candidateType": 1,
"deleted": false,
"id": "candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG",
"ip": "1.1.1.1",
"networkType": 1,
"port": 33911,
"priority": 2130706431,
"protocol": "udp",
"relayProtocol": "",
"timestamp": 1694738831184,
"transportId": "",
"type": "local-candidate",
"url": ""
},
"candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG-candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG": {
"availableIncomingBitrate": 0,
"availableOutgoingBitrate": 0,
"bytesReceived": 0,
"bytesSent": 0,
"circuitBreakerTriggerCount": 0,
"consentExpiredTimestamp": -6795364578871,
"consentRequestsSent": 0,
"currentRoundTripTime": 0,
"firstRequestTimestamp": -6795364578871,
"id": "candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG-candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG",
"lastPacketReceivedTimestamp": -6795364578871,
"lastPacketSentTimestamp": -6795364578871,
"lastRequestTimestamp": -6795364578871,
"lastResponseTimestamp": -6795364578871,
"localCandidateId": "candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG",
"nominated": false,
"packetsReceived": 0,
"packetsSent": 0,
"remoteCandidateId": "candidate:DgxUJLl3TtmkwrDZ9tb5Hon1rBev3wsG",
"requestsReceived": 0,
"requestsSent": 0,
"responsesReceived": 0,
"responsesSent": 0,
"retransmissionsReceived": 0,
"retransmissionsSent": 0,
"state": "succeeded",
"timestamp": 1694738831184,
"totalRoundTripTime": 0,
"transportId": "",
"type": "candidate-pair"
},
"candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG-candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor": {
"availableIncomingBitrate": 0,
"availableOutgoingBitrate": 0,
"bytesReceived": 0,
"bytesSent": 0,
"circuitBreakerTriggerCount": 0,
"consentExpiredTimestamp": -6795364578871,
"consentRequestsSent": 0,
"currentRoundTripTime": 0,
"firstRequestTimestamp": -6795364578871,
"id": "candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG-candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor",
"lastPacketReceivedTimestamp": -6795364578871,
"lastPacketSentTimestamp": -6795364578871,
"lastRequestTimestamp": -6795364578871,
"lastResponseTimestamp": -6795364578871,
"localCandidateId": "candidate:o+5MvljjtUpHLjpFgOD0Q5O26MZiQdpG",
"nominated": true,
"packetsReceived": 0,
"packetsSent": 0,
"remoteCandidateId": "candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor",
"requestsReceived": 0,
"requestsSent": 0,
"responsesReceived": 0,
"responsesSent": 0,
"retransmissionsReceived": 0,
"retransmissionsSent": 0,
"state": "succeeded",
"timestamp": 1694738831184,
"totalRoundTripTime": 0,
"transportId": "",
"type": "candidate-pair"
},
"candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor": {
"candidateType": 3,
"deleted": false,
"id": "candidate:vaXVWPrEf6krzT6Th5L2t/hWnBzdNbor",
"ip": "2.2.2.2",
"networkType": 1,
"port": 55981,
"priority": 1862270975,
"protocol": "udp",
"relayProtocol": "",
"timestamp": 1694738831184,
"transportId": "",
"type": "remote-candidate",
"url": ""
},
"certificate-1694738825176262915": {
"base64Certificate": "MIIBHTCBxaADAgECAhEArq0anmALWLbQz0z9pbirTDAKBggqhkjOPQQDAjARMQ8wDQYDVQQDEwZXZWJSVEMwHhcNMjMwOTE0MDA0NzA1WhcNMjMxMDE0MDA0NzA1WjARMQ8wDQYDVQQDEwZXZWJSVEMwWTATBgcqhkjOPQIBBggqhkjOPQMBBwNCAATwjH0eeeIRlNUK2wRKkcxluNzDbziaZVwMp2P4fGCIFGWasRnmJwj4odyM4GqQ0fA_q8UJnJDNMPx0d2lqdb8JMAoGCCqGSM49BAMCA0cAMEQCIHrv_taaK3XhRVx41hkf585Qn2WSeJ6k4vEchiybWnQaAiAGWes4sfWVP6DQTK8H5UuYdB2p77f33TaGtTeqoffbcw",
"fingerprint": "5a:74:5f:20:6c:1b:ac:8e:fd:0c:74:09:69:c2:74:ac:44:7d:b9:7e:79:61:3f:3c:d2:b8:03:d3:58:bb:9b:5b",
"fingerprintAlgorithm": "sha-256",
"id": "certificate-1694738825176262915",
"issuerCertificateId": "CN=WebRTC",
"timestamp": 1694738831184,
"type": "certificate"
},
"DataChannel-1694738825177300312": {
"bytesReceived": 0,
"bytesSent": 0,
"dataChannelIdentifier": 1,
"id": "DataChannel-1694738825177300312",
"label": "-",
"messagesReceived": 0,
"messagesSent": 0,
"protocol": "",
"state": 2,
"timestamp": 1694738831184,
"transportId": "",
"type": "data-channel"
},
"iceTransport": {
"bytesReceived": 1312,
"bytesSent": 1213,
"dtlsCipher": "",
"dtlsState": 0,
"iceRole": 0,
"id": "iceTransport",
"localCertificateId": "",
"packetsReceived": 0,
"packetsSent": 0,
"remoteCertificateId": "",
"rtcpTransportStatsId": "",
"selectedCandidatePairId": "",
"srtpCipher": "",
"timestamp": 1694738831184,
"type": "transport"
},
"PeerConnection-1694738825174104883": {
"dataChannelsAccepted": 0,
"dataChannelsClosed": 0,
"dataChannelsOpened": 1,
"dataChannelsRequested": 1,
"id": "PeerConnection-1694738825174104883",
"timestamp": 1694738831184,
"type": "peer-connection"
},
"RTPCodec-1694738825174085391": {
"channels": 0,
"clockRate": 90000,
"codecType": "",
"id": "RTPCodec-1694738825174085391",
"implementation": "",
"mimeType": "video/H264",
"payloadType": 96,
"sdpFmtpLine": "level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f",
"timestamp": 1694738831184,
"transportId": "",
"type": "codec"
},
"sctpTransport": {
"bytesReceived": 240,
"bytesSent": 252,
"dtlsCipher": "",
"dtlsState": 0,
"iceRole": 0,
"id": "sctpTransport",
"localCertificateId": "",
"packetsReceived": 0,
"packetsSent": 0,
"remoteCertificateId": "",
"rtcpTransportStatsId": "",
"selectedCandidatePairId": "",
"srtpCipher": "",
"timestamp": 1694738831184,
"type": "transport"
}
}
I have nailed it down. Problem is caused by fact that Agent.connectionStateRoutine creates new goroutine to send new state (https://github.com/pion/ice/blob/master/agent_handlers.go#L52). Sometimes goroutine created to send Checking state is not executed immediately, but after another one used to send Connected state. I tried to remove go keyword there and looks that it fixed this problem. To avoid potential problems elsewhere, it would be good to add some buffer to chanState channel too.
Fixed by https://github.com/pion/ice/commit/67cc918a518d3b3dd1887b07434331dabc846702