Time out when negotiating connection #1256

ppv-milestone · 2024-12-11T12:49:26Z

ppv-milestone
Dec 11, 2024

Hi,
I have an implementation using WebRTC part of SIPSorcery in place which 2 out of 3 times works fine, but approximately every third attempt the flow seems to stop midway and then eventually times out. The logs will show the below (I have replaced TURN server address with 1.2.3.4, TURN server uri with TURNURI and certificate with XYZ), but then next line will be a timeout:

2024-12-10 09:54:56.528+01:00 INFO - sipsorcery: No DTLS certificate is provided in the configuration
2024-12-10 09:54:56.553+01:00 INFO - sipsorcery: RTCPeerConnection created with DTLS certificate with fingerprint sha-256 AC:F4:AC:A2:D6:EA:71:27:70:EC:BB:5E:82:DF:DE:92:B0:C9:47:E8:93:B4:63:D8:8A:17:E5:D3:6E:95:29:F3 and signature algorithm SHA256withECDSA.
2024-12-10 09:54:56.570+01:00 INFO - sipsorcery: -----BEGIN CERTIFICATE-----
XYZ
-----END CERTIFICATE-----
2024-12-10 09:54:56.587+01:00 INFO - sipsorcery: CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0.
2024-12-10 09:54:56.611+01:00 INFO - sipsorcery: CreateBoundSocket attempting to create and bind socket(s) on [::]:0 using protocol Udp.
2024-12-10 09:54:56.633+01:00 INFO - sipsorcery: CreateBoundSocket successfully bound on [::]:57918, dual mode True.
2024-12-10 09:54:56.649+01:00 INFO - sipsorcery: Successfully bound RTP socket [::]:57918 (dual mode True).
2024-12-10 09:54:56.671+01:00 INFO - sipsorcery: CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0.
2024-12-10 09:54:56.689+01:00 INFO - sipsorcery: CreateBoundSocket attempting to create and bind socket(s) on [::]:0 using protocol Tcp.
2024-12-10 09:54:56.713+01:00 INFO - sipsorcery: CreateBoundSocket even port required, closing socket on [::]:34347 and retrying on 34348.
2024-12-10 09:54:56.737+01:00 INFO - sipsorcery: Successfully bound RTP socket [::]:34348 (dual mode True).
2024-12-10 09:54:56.759+01:00 INFO - sipsorcery: RTPChannel for [::]:57918 started.
2024-12-10 09:54:56.778+01:00 INFO - SIPSorcery.Net.SctpDataReceiver: SCTP windows size for data receiver set at 218.
2024-12-10 09:54:56.793+01:00 INFO - sipsorcery: SCTP creating DTLS based association, is DTLS client False, ID 5000:5000:57918.
2024-12-10 09:54:56.814+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI.
2024-12-10 09:54:56.837+01:00 INFO - sipsorcery: RTPIceChannel TCP for [::]:57918 started.
2024-12-10 09:54:56.874+01:00 INFO - sipsorcery: RTP ICE Channel discovered 0 local candidates.
2024-12-10 09:54:56.896+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI.
2024-12-10 09:54:56.915+01:00 INFO - sipsorcery: Attempting to resolve STUN server URI turn:TURNURI.
2024-12-10 09:54:56.932+01:00 INFO - sipsorcery: ICE server turn:TURNURI successfully resolved to 1.2.3.4:443.
2024-12-10 09:54:56.973+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.116+01:00 INFO - sipsorcery: SendOverTCP status: True endpoint: [::ffff:1.2.3.4]:443
2024-12-10 09:54:57.162+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.225+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.289+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.351+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.413+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.477+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI with address 1.2.3.4:443.
2024-12-10 09:54:57.490+01:00 INFO - sipsorcery: TURN allocate success response received for ICE server check to turn:TURNURI.
2024-12-10 09:54:57.501+01:00 INFO - sipsorcery: Adding relay ICE candidate for ICE server turn:TURNURI and 1.2.3.4:27356.
2024-12-10 09:54:57.539+01:00 INFO - sipsorcery: ICE RTP channel stopping ICE server checks in gathering state complete and connection state new.
2024-12-10 09:54:58.552+01:00 INFO - sipsorcery: RTP ICE Channel remote credentials set.
2024-12-10 09:54:58.576+01:00 INFO - sipsorcery: RTP ICE Channel received remote candidate: 2558687369 1 udp 16777215 1.2.3.4 31186 typ relay raddr 10.24.31.13 rport 34750 generation 0
2024-12-10 09:54:58.596+01:00 INFO - sipsorcery: Remote ICE candidate not added as no available ICE session for component rtcp.
2024-12-10 09:54:58.609+01:00 INFO - sipsorcery: Adding new candidate pair to checklist for: udp:1.2.3.4:27356 (relay)->udp:1.2.3.4:31186 (relay)
2024-12-10 09:54:58.611+01:00 INFO - sipsorcery: LogRemoteSDPSsrcAttributes: Audio:[ ] 
 Video: [  ]
2024-12-10 09:54:58.622+01:00 INFO - sipsorcery: ICE RTP channel sending TURN permissions request 1 to server turn:TURNURI for peer 1.2.3.4:31186 (TxID: LWEQUAFGHWIN).
2024-12-10 09:54:58.773+01:00 INFO - sipsorcery: A TURN Create Permission success response was received from [::]:0 (TxID: LWEQUAFGHWIN).
2024-12-10 09:54:58.800+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:27356 (relay)->udp:1.2.3.4:31186 (relay) from [::]:57918 to relay at 1.2.3.4:443 (use candidate False).
2024-12-10 09:54:58.945+01:00 INFO - sipsorcery: ICE RTP channel binding response state Succeeded as Controller for udp:1.2.3.4:31186 (relay)
2024-12-10 09:54:58.955+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:27356 (relay)->udp:1.2.3.4:31186 (relay) from [::]:57918 to relay at 1.2.3.4:443 (use candidate True).

The times where it work I get the exact same, but then it will continue with this:

2024-12-10 09:55:43.264+01:00 INFO - sipsorcery: ICE RTP channel remote peer nominated entry from binding response udp:1.2.3.4:33271 (relay)
2024-12-10 09:55:43.275+01:00 INFO - sipsorcery: ICE RTP channel connected after 2459ms udp:1.2.3.4:33270 (relay)->udp:1.2.3.4:33271 (relay).
2024-12-10 09:55:43.315+01:00 INFO - sipsorcery: ICE connected to remote end point 1.2.3.4:33271.
2024-12-10 09:55:43.337+01:00 INFO - sipsorcery: Starting DLS handshake with role passive.
2024-12-10 09:55:43.356+01:00 INFO - sipsorcery: RTCPeerConnection DoDtlsHandshake started.
2024-12-10 09:55:43.374+01:00 INFO - sipsorcery: DTLS commencing handshake as server.
2024-12-10 09:55:43.398+01:00 INFO - sipsorcery: Server offered cipher suites:
 TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
 TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
 TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
 DRAFT_TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
2024-12-10 09:55:43.408+01:00 INFO - sipsorcery: Client offered cipher suites:
 TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
 TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
 TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
 TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
2024-12-10 09:55:43.428+01:00 INFO - sipsorcery: Selected cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256. Using SHA256withECDSA certificate with fingerprint sha-256 EA:B1:56:02:CD:F0:54:73:7F:73:5A:3E:27:31:42:0D:2D:35:CA:64:E5:00:30:3B:60:3F:9A:2D:4C:4B:67:23.
2024-12-10 09:55:43.722+01:00 INFO - sipsorcery: RTCPeerConnection DTLS handshake result True, is handshake complete True.
2024-12-10 09:55:43.747+01:00 INFO - sipsorcery: Remote peer DTLS certificate, signature algorithm SHA256withECDSA.
2024-12-10 09:55:43.766+01:00 INFO - sipsorcery: -----BEGIN CERTIFICATE-----
XYZ
-----END CERTIFICATE-----
2024-12-10 09:55:43.780+01:00 INFO - sipsorcery: RTCPeerConnection remote certificate fingerprint matched expected value of FE:50:1F:8B:5F:A8:AD:7C:57:A1:6A:D9:FF:23:12:ED:BF:5B:A3:49:44:8C:90:44:AB:0D:1E:DE:18:E0:75:C4 for sha-256.

We have another web based client towards the same servers and do not see the same issue there. Does anyone have an idea what could be the reason why "ICE RTP channel sending connectivity check for" often times out?

sipsorcery · 2024-12-14T20:09:27Z

sipsorcery
Dec 14, 2024
Maintainer

I can replicate the same behaviour and log messages if I re-use an RTCPeerConnection instance. Each instance is only intended to be used once. For each new WebRTC peer connection you should be creating a brand new instance.

If it helps I use the webrtccmdline tool to test scenarios like this.

Signalling server peer:

sipsorcery\examples\webrtccmdline>dotnet run --ws --stun turn:azamicrok8s?transport=tcp --relayonly --accepticetypes=relay

Signalling client peer:

sipsorcery\examples\webrtccmdline>dotnet run --wsclient ws://127.0.0.1:8081 --stun turn:azamicrok8s?transport=tcp --relayonly --accepticetypes=relay

9 replies

sipsorcery Dec 27, 2024
Maintainer

I'm still trying to reproduce this. It turns out the issue I had previously was due to my ICE candidates not being exchanged properly.

Are you able to test your TURN server connection with UDP instead of TCP? It would be useful to know if the issue happens with UDP as well.

ppv-milestone Jan 2, 2025
Author

Sorry for the delayed response - I have been offline for a few days due to the holidays.
The issue happens with UDP as well and I get quite similar logs:

2025-01-02 08:52:40.439+01:00 INFO - sipsorcery: No DTLS certificate is provided in the configuration
2025-01-02 08:52:40.441+01:00 INFO - sipsorcery: RTCPeerConnection created with DTLS certificate with fingerprint sha-256 AE:92:80:EE:41:0E:44:47:8B:FA:32:F1:2D:92:DD:CF:00:86:72:E4:6E:54:91:52:27:7B:99:48:C9:AE:18:23 and signature algorithm SHA256withECDSA.
2025-01-02 08:52:40.442+01:00 INFO - sipsorcery: -----BEGIN CERTIFICATE-----
XYZ
-----END CERTIFICATE-----
2025-01-02 08:52:40.442+01:00 INFO - sipsorcery: CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0.
2025-01-02 08:52:40.443+01:00 INFO - sipsorcery: CreateBoundSocket attempting to create and bind socket(s) on [::]:0 using protocol Udp.
2025-01-02 08:52:40.444+01:00 INFO - sipsorcery: CreateBoundSocket successfully bound on [::]:61704, dual mode True.
2025-01-02 08:52:40.445+01:00 INFO - sipsorcery: Successfully bound RTP socket [::]:61704 (dual mode True).
2025-01-02 08:52:40.445+01:00 INFO - sipsorcery: RTPChannel for [::]:61704 started.
2025-01-02 08:52:40.446+01:00 INFO - SIPSorcery.Net.SctpDataReceiver: SCTP windows size for data receiver set at 218.
2025-01-02 08:52:40.447+01:00 INFO - sipsorcery: SCTP creating DTLS based association, is DTLS client False, ID 5000:5000:61704.
2025-01-02 08:52:40.448+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI:443.
2025-01-02 08:52:40.449+01:00 INFO - sipsorcery: RTP ICE Channel discovered 0 local candidates.
2025-01-02 08:52:40.450+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI:443.
2025-01-02 08:52:40.451+01:00 INFO - sipsorcery: Attempting to resolve STUN server URI turn:TURNURI:443.
2025-01-02 08:52:40.452+01:00 INFO - sipsorcery: ICE server turn:TURNURI:443 successfully resolved to 1.2.3.4:443.
2025-01-02 08:52:40.502+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-02 08:52:40.565+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-02 08:52:40.627+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-02 08:52:40.691+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-02 08:52:40.749+01:00 INFO - sipsorcery: TURN allocate success response received for ICE server check to turn:TURNURI:443.
2025-01-02 08:52:40.750+01:00 INFO - sipsorcery: Adding relay ICE candidate for ICE server turn:TURNURI:443 and 1.2.3.4:31864.
2025-01-02 08:52:40.752+01:00 INFO - sipsorcery: ICE RTP channel stopping ICE server checks in gathering state complete and connection state new.
2025-01-02 08:52:41.514+01:00 INFO - sipsorcery: RTP ICE Channel remote credentials set.
2025-01-02 08:52:41.515+01:00 INFO - sipsorcery: RTP ICE Channel received remote candidate: 2558687369 1 udp 16777215 1.2.3.4 28920 typ relay raddr 0.0.0.0 rport 57045 generation 0
2025-01-02 08:52:41.515+01:00 INFO - sipsorcery: Remote ICE candidate not added as no available ICE session for component rtcp.
2025-01-02 08:52:41.516+01:00 INFO - sipsorcery: LogRemoteSDPSsrcAttributes: Audio:[ ] 
 Video: [  ]
2025-01-02 08:52:41.560+01:00 INFO - sipsorcery: Adding new candidate pair to checklist for: udp:1.2.3.4:31864 (relay)->udp:1.2.3.4:28920 (relay)
2025-01-02 08:52:41.561+01:00 INFO - sipsorcery: ICE RTP channel sending TURN permissions request 1 to server turn:TURNURI:443 for peer 1.2.3.4:28920 (TxID: QZYFCALJTICH).
2025-01-02 08:52:41.684+01:00 INFO - sipsorcery: A TURN Create Permission success response was received from 1.2.3.4:443 (TxID: QZYFCALJTICH).
2025-01-02 08:52:41.686+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:31864 (relay)->udp:1.2.3.4:28920 (relay) from [::]:61704 to relay at 1.2.3.4:443 (use candidate False).
2025-01-02 08:52:41.809+01:00 INFO - sipsorcery: ICE RTP channel binding response state Succeeded as Controller for udp:1.2.3.4:28920 (relay)
2025-01-02 08:52:41.810+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:31864 (relay)->udp:1.2.3.4:28920 (relay) from [::]:61704 to relay at 1.2.3.4:443 (use candidate True).

ppv-milestone Jan 2, 2025
Author

In an attempt to try to figure out what goes different between when connection is established correctly and when not, I started adding some logging various places (as debugging will cause the issue to stop from happening).
First thing I have observed which might not be of any relevance, but still seems to be a very consistent difference between successful and non-successful attempts is that when the attempt is successful, slightly before (approximately 40ms) the "binding response state Succeeded as Controller" I get one log indication that a STUN message with MessageType BindingRequest has been received (line 1970 in RtpIceChannel). Also, immeditately after (within 1ms) the "sending connectivity check" message in the logs I get another Binding Request, but not any more of these before the "remote peer nominated entry from binding response" log indicating that a successful binding response has been received approximately 120 ms later.
When the attempt is non-successful I see no BindingRequest before, but the same one within the 1ms after "sending connectivity check", but I then always get exactly two more BindingRequests within the next approximately 120 ms until the log then goes silent until I close the connection attempt due to timeout.
To summarize, if we name BindingRequest 'BR', and the "binding response state Succeeded as Controller" 'SUC', and the "sending connectivity check" 'SCC', I get the following sequences consistently:
Successful: BR, SUC, SCC, BR
Non-successful: SUC, SCC, BR, BR, BR
I am sorry if this is not of any relevance and honestly maybe not very well described, but since the problem seems to be about timing, I think it is worth sharing since it seems to be so consistent.

sipsorcery Jan 2, 2025
Maintainer

Can you add the two debug messages as below to your app. The idea is to see if a STUN response is being received to the use candidate check.

pc.GetRtpChannel().OnStunMessageSent += (msg, ep, isRelay) => logger.LogDebug($"STUN {msg.Header.MessageType} message sent to {ep} (is relay {isRelay}).");
pc.GetRtpChannel().OnStunMessageReceived += (msg, ep, isRelay) => logger.LogDebug($"STUN {msg.Header.MessageType} message received from {ep} (is relay {isRelay}).");

ppv-milestone Jan 3, 2025
Author

I have now run again with these added (log starts with "INFO - WebRTC:".
Successful attempt:

2025-01-03 07:34:55.033+01:00 INFO - sipsorcery: No DTLS certificate is provided in the configuration
2025-01-03 07:34:55.035+01:00 INFO - sipsorcery: RTCPeerConnection created with DTLS certificate with fingerprint sha-256 3B:D3:D0:C0:7B:AA:B0:B1:21:39:58:6F:6C:E6:71:4F:04:CB:FE:58:2F:47:81:2F:79:C8:BA:73:C0:AC:B6:9A and signature algorithm SHA256withECDSA.
2025-01-03 07:34:55.035+01:00 INFO - sipsorcery: -----BEGIN CERTIFICATE-----
XYZ
-----END CERTIFICATE-----
2025-01-03 07:34:55.036+01:00 INFO - sipsorcery: CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0.
2025-01-03 07:34:55.036+01:00 INFO - sipsorcery: CreateBoundSocket attempting to create and bind socket(s) on [::]:0 using protocol Udp.
2025-01-03 07:34:55.037+01:00 INFO - sipsorcery: CreateBoundSocket successfully bound on [::]:56188, dual mode True.
2025-01-03 07:34:55.038+01:00 INFO - sipsorcery: Successfully bound RTP socket [::]:56188 (dual mode True).
2025-01-03 07:34:55.039+01:00 INFO - sipsorcery: RTPChannel for [::]:56188 started.
2025-01-03 07:34:55.040+01:00 INFO - SIPSorcery.Net.SctpDataReceiver: SCTP windows size for data receiver set at 218.
2025-01-03 07:34:55.040+01:00 INFO - sipsorcery: SCTP creating DTLS based association, is DTLS client False, ID 5000:5000:56188.
2025-01-03 07:34:55.041+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI:443.
2025-01-03 07:34:55.042+01:00 INFO - sipsorcery: RTP ICE Channel discovered 0 local candidates.
2025-01-03 07:34:55.043+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI:443.
2025-01-03 07:34:55.043+01:00 INFO - sipsorcery: Attempting to resolve STUN server URI turn:TURNURI:443.
2025-01-03 07:34:55.045+01:00 INFO - sipsorcery: ICE server turn:TURNURI:443 successfully resolved to 1.2.3.4:443.
2025-01-03 07:34:55.117+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:34:55.117+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.177+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:34:55.178+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.238+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:34:55.239+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.262+01:00 INFO - WebRTC: STUN AllocateErrorResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.301+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:34:55.301+01:00 INFO - WebRTC: STUN AllocateErrorResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.302+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.361+01:00 INFO - WebRTC: STUN AllocateErrorResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.364+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:34:55.365+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.424+01:00 INFO - WebRTC: STUN AllocateSuccessResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:34:55.424+01:00 INFO - sipsorcery: TURN allocate success response received for ICE server check to turn:TURNURI:443.
2025-01-03 07:34:55.425+01:00 INFO - sipsorcery: Adding relay ICE candidate for ICE server turn:TURNURI:443 and 1.2.3.4:28538.
2025-01-03 07:34:55.488+01:00 INFO - sipsorcery: ICE RTP channel stopping ICE server checks in gathering state complete and connection state new.
2025-01-03 07:34:56.502+01:00 INFO - sipsorcery: RTP ICE Channel remote credentials set.
2025-01-03 07:34:56.503+01:00 INFO - sipsorcery: RTP ICE Channel received remote candidate: 2558687369 1 udp 16777215 1.2.3.4 30918 typ relay raddr 0.0.0.0 rport 38702 generation 0
2025-01-03 07:34:56.504+01:00 INFO - sipsorcery: Remote ICE candidate not added as no available ICE session for component rtcp.
2025-01-03 07:34:56.504+01:00 INFO - sipsorcery: LogRemoteSDPSsrcAttributes: Audio:[ ] 
 Video: [  ]
2025-01-03 07:34:56.505+01:00 INFO - WebRTC: STUN AllocateSuccessResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:34:56.570+01:00 INFO - sipsorcery: Adding new candidate pair to checklist for: udp:1.2.3.4:28538 (relay)->udp:1.2.3.4:30918 (relay)
2025-01-03 07:34:56.571+01:00 INFO - sipsorcery: ICE RTP channel sending TURN permissions request 1 to server turn:TURNURI:443 for peer 1.2.3.4:30918 (TxID: IDQZOVANAKMQ).
2025-01-03 07:34:56.572+01:00 INFO - WebRTC: STUN CreatePermission message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:34:56.694+01:00 INFO - WebRTC: STUN CreatePermissionSuccessResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:34:56.694+01:00 INFO - sipsorcery: A TURN Create Permission success response was received from 1.2.3.4:443 (TxID: IDQZOVANAKMQ).
2025-01-03 07:34:56.696+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:28538 (relay)->udp:1.2.3.4:30918 (relay) from [::]:56188 to relay at 1.2.3.4:443 (use candidate False).
2025-01-03 07:34:56.697+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.722+01:00 INFO - WebRTC: STUN BindingRequest message received from 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:56.723+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.723+01:00 INFO - WebRTC: STUN BindingSuccessResponse message sent to 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:56.820+01:00 INFO - WebRTC: STUN BindingSuccessResponse message received from 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:56.820+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:28538 (relay)->udp:1.2.3.4:30918 (relay) from [::]:56188 to relay at 1.2.3.4:443 (use candidate True).
2025-01-03 07:34:56.821+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.821+01:00 INFO - WebRTC: STUN BindingRequest message received from 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:56.821+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.821+01:00 INFO - WebRTC: STUN BindingSuccessResponse message sent to 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:56.943+01:00 INFO - WebRTC: STUN BindingSuccessResponse message received from 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:56.944+01:00 INFO - sipsorcery: ICE RTP channel connected after 1902ms udp:1.2.3.4:28538 (relay)->udp:1.2.3.4:30918 (relay).
2025-01-03 07:34:56.945+01:00 INFO - sipsorcery: ICE connected to remote end point 1.2.3.4:30918.
2025-01-03 07:34:56.945+01:00 INFO - sipsorcery: Starting DLS handshake with role passive.
2025-01-03 07:34:56.945+01:00 INFO - sipsorcery: RTCPeerConnection DoDtlsHandshake started.
2025-01-03 07:34:56.946+01:00 INFO - sipsorcery: DTLS commencing handshake as server.
2025-01-03 07:34:56.947+01:00 INFO - sipsorcery: Server offered cipher suites:
 TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
 TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
 TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
 DRAFT_TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
2025-01-03 07:34:56.947+01:00 INFO - sipsorcery: Client offered cipher suites:
 TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
 TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
 TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
 TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
2025-01-03 07:34:56.948+01:00 INFO - sipsorcery: Selected cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256. Using SHA256withECDSA certificate with fingerprint sha-256 3B:D3:D0:C0:7B:AA:B0:B1:21:39:58:6F:6C:E6:71:4F:04:CB:FE:58:2F:47:81:2F:79:C8:BA:73:C0:AC:B6:9A.
2025-01-03 07:34:56.948+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.949+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.950+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.951+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:56.952+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.077+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.078+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.079+01:00 INFO - sipsorcery: RTCPeerConnection DTLS handshake result True, is handshake complete True.
2025-01-03 07:34:57.080+01:00 INFO - sipsorcery: Remote peer DTLS certificate, signature algorithm SHA256withECDSA.
2025-01-03 07:34:57.081+01:00 INFO - sipsorcery: -----BEGIN CERTIFICATE-----
XYZ
-----END CERTIFICATE-----
2025-01-03 07:34:57.082+01:00 INFO - sipsorcery: RTCPeerConnection remote certificate fingerprint matched expected value of 6E:84:DF:BC:B2:C5:50:67:12:EF:51:6C:35:A7:42:05:DB:43:8D:1E:84:74:7F:30:96:51:34:1E:98:E8:77:9F for sha-256.
2025-01-03 07:34:57.100+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.175+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.233+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.300+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.360+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.421+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.492+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.552+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.620+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.679+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.740+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.807+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.872+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:57.940+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.000+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.061+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.127+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.193+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.261+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.321+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.381+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.453+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.514+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.580+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.640+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.699+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.773+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.833+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.902+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:58.956+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:59.124+01:00 INFO - WebRTC: STUN BindingRequest message received from 1.2.3.4:30918 (is relay True).
2025-01-03 07:34:59.125+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:34:59.125+01:00 INFO - WebRTC: STUN BindingSuccessResponse message sent to 1.2.3.4:30918 (is relay True).

Failed attempt:

2025-01-03 07:35:09.383+01:00 INFO - sipsorcery: No DTLS certificate is provided in the configuration
2025-01-03 07:35:09.385+01:00 INFO - sipsorcery: RTCPeerConnection created with DTLS certificate with fingerprint sha-256 D8:75:25:7A:97:53:74:50:6B:B7:17:51:9F:A3:1B:D7:69:CC:1E:00:1C:15:8E:E8:C3:71:E0:D4:6F:66:63:48 and signature algorithm SHA256withECDSA.
2025-01-03 07:35:09.386+01:00 INFO - sipsorcery: -----BEGIN CERTIFICATE-----
XYZ
-----END CERTIFICATE-----
2025-01-03 07:35:09.387+01:00 INFO - sipsorcery: CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0.
2025-01-03 07:35:09.387+01:00 INFO - sipsorcery: CreateBoundSocket attempting to create and bind socket(s) on [::]:0 using protocol Udp.
2025-01-03 07:35:09.389+01:00 INFO - sipsorcery: CreateBoundSocket even port required, closing socket on [::]:61581 and retrying on 61582.
2025-01-03 07:35:09.390+01:00 INFO - sipsorcery: Successfully bound RTP socket [::]:61582 (dual mode True).
2025-01-03 07:35:09.390+01:00 INFO - sipsorcery: RTPChannel for [::]:61582 started.
2025-01-03 07:35:09.391+01:00 INFO - SIPSorcery.Net.SctpDataReceiver: SCTP windows size for data receiver set at 218.
2025-01-03 07:35:09.392+01:00 INFO - sipsorcery: SCTP creating DTLS based association, is DTLS client False, ID 5000:5000:61582.
2025-01-03 07:35:09.393+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI:443.
2025-01-03 07:35:09.395+01:00 INFO - sipsorcery: RTP ICE Channel discovered 0 local candidates.
2025-01-03 07:35:09.396+01:00 INFO - sipsorcery: Adding ICE server for turn:TURNURI:443.
2025-01-03 07:35:09.397+01:00 INFO - sipsorcery: Attempting to resolve STUN server URI turn:TURNURI:443.
2025-01-03 07:35:09.399+01:00 INFO - sipsorcery: ICE server turn:TURNURI:443 successfully resolved to 1.2.3.4:443.
2025-01-03 07:35:09.448+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:35:09.449+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.512+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:35:09.513+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.571+01:00 INFO - WebRTC: STUN AllocateErrorResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.574+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:35:09.575+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.634+01:00 INFO - WebRTC: STUN AllocateErrorResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.638+01:00 INFO - sipsorcery: Sending TURN allocate request to ICE server turn:TURNURI:443 with address 1.2.3.4:443.
2025-01-03 07:35:09.639+01:00 INFO - WebRTC: STUN Allocate message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.697+01:00 INFO - WebRTC: STUN AllocateSuccessResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:35:09.697+01:00 INFO - sipsorcery: TURN allocate success response received for ICE server check to turn:TURNURI:443.
2025-01-03 07:35:09.697+01:00 INFO - sipsorcery: Adding relay ICE candidate for ICE server turn:TURNURI:443 and 1.2.3.4:33080.
2025-01-03 07:35:09.700+01:00 INFO - sipsorcery: ICE RTP channel stopping ICE server checks in gathering state complete and connection state new.
2025-01-03 07:35:10.657+01:00 INFO - sipsorcery: RTP ICE Channel remote credentials set.
2025-01-03 07:35:10.658+01:00 INFO - sipsorcery: RTP ICE Channel received remote candidate: 4006836086 1 udp 16777215 1.2.3.4 31307 typ relay raddr 0.0.0.0 rport 55533 generation 0
2025-01-03 07:35:10.659+01:00 INFO - sipsorcery: Remote ICE candidate not added as no available ICE session for component rtcp.
2025-01-03 07:35:10.659+01:00 INFO - sipsorcery: LogRemoteSDPSsrcAttributes: Audio:[ ] 
 Video: [  ]
2025-01-03 07:35:10.661+01:00 INFO - WebRTC: STUN AllocateSuccessResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:35:10.709+01:00 INFO - sipsorcery: Adding new candidate pair to checklist for: udp:1.2.3.4:33080 (relay)->udp:1.2.3.4:31307 (relay)
2025-01-03 07:35:10.710+01:00 INFO - sipsorcery: ICE RTP channel sending TURN permissions request 1 to server turn:TURNURI:443 for peer 1.2.3.4:31307 (TxID: QYGRELIJPFAW).
2025-01-03 07:35:10.710+01:00 INFO - WebRTC: STUN CreatePermission message sent to 1.2.3.4:443 (is relay False).
2025-01-03 07:35:10.903+01:00 INFO - WebRTC: STUN CreatePermissionSuccessResponse message received from 1.2.3.4:443 (is relay False).
2025-01-03 07:35:10.904+01:00 INFO - sipsorcery: A TURN Create Permission success response was received from 1.2.3.4:443 (TxID: QYGRELIJPFAW).
2025-01-03 07:35:10.958+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:33080 (relay)->udp:1.2.3.4:31307 (relay) from [::]:61582 to relay at 1.2.3.4:443 (use candidate False).
2025-01-03 07:35:10.958+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:35:11.081+01:00 INFO - WebRTC: STUN BindingSuccessResponse message received from 1.2.3.4:31307 (is relay True).
2025-01-03 07:35:11.081+01:00 INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:33080 (relay)->udp:1.2.3.4:31307 (relay) from [::]:61582 to relay at 1.2.3.4:443 (use candidate True).
2025-01-03 07:35:11.082+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:35:11.082+01:00 INFO - WebRTC: STUN BindingRequest message received from 1.2.3.4:31307 (is relay True).
2025-01-03 07:35:11.082+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:35:11.082+01:00 INFO - WebRTC: STUN BindingSuccessResponse message sent to 1.2.3.4:31307 (is relay True).
2025-01-03 07:35:11.095+01:00 INFO - WebRTC: STUN BindingRequest message received from 1.2.3.4:31307 (is relay True).
2025-01-03 07:35:11.096+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:35:11.096+01:00 INFO - WebRTC: STUN BindingSuccessResponse message sent to 1.2.3.4:31307 (is relay True).
2025-01-03 07:35:11.203+01:00 INFO - WebRTC: STUN BindingRequest message received from 1.2.3.4:31307 (is relay True).
2025-01-03 07:35:11.203+01:00 INFO - WebRTC: STUN SendIndication message sent to 1.2.3.4:443 (is relay True).
2025-01-03 07:35:11.204+01:00 INFO - WebRTC: STUN BindingSuccessResponse message sent to 1.2.3.4:31307 (is relay True).

I am truely grateful for your continued support on this. Thanks! Please let me know if there is anything else I should try out.

sipsorcery · 2025-01-03T09:53:26Z

sipsorcery
Jan 3, 2025
Maintainer

Thanks for the additional logs. The key difference between the success and failure cases is this log message:

WebRTC: STUN BindingSuccessResponse message received from 1.2.3.4:30918 (is relay True).

In the success case that STUN response is received AFTER the ICE candidate is nominated, which is indicated in the log message below with the use candidate True.

INFO - sipsorcery: ICE RTP channel sending connectivity check for udp:1.2.3.4:28538 (relay)->udp:1.2.3.4:30918 (relay) from [::]:56188 to relay at 1.2.3.4:443 (use candidate True).

The question is now why isn't the STUN binding success response received from the TURN server in some cases. If you're able to use WireShark it would be very helpful to get a packet capture of the STUN messages to/from the TURN server during the success and failure cases. That should fairly definitively point to the sipsorcery library being the culprit or not. If you do capture a WireShark trace you can send it directly to me at [email protected] to avoid publishing you IP addresses.

8 replies

ppv-milestone Jan 6, 2025
Author

The other end is a streaming server that should receive the audio streamed by my client. All communication is going through a coturn server. Should the BindingSuccessResponse be issued by the coturn server or should it be just be sent by the coturn server in order to reflect something triggered by the remote host?
I do also have a webbased client running in Chrome, but otherwise with same setup (connecting through coturn to the streaming server), but with that one I have never been able to replicate the issue, so that is why I am suspecting it is something with SipSorcery (or the combination of SipSorcery and coturn).

sipsorcery Jan 6, 2025
Maintainer

It doesn't seem to be coturn as there are two way messages flwoing through it in the failure case (if it was coturn I'd expect to see only one-way). Are you able to get the streaming server logs? It would be useful to compare those in the success and failure cases.

ppv-milestone Jan 6, 2025
Author

From what I have been told it should be coturn, but I will verify that, and have also reached out to the server team. They are in another time zone, so might take a while.

ppv-milestone Jan 20, 2025
Author

We have now tried running with a coturn server we set up ourselves in order to verify whether it happens there as well, but also to get access to the logs. The issue happens less frequently with this server, but it still happens, and the logs does not really provide any clue about what happens. Any suggestions on something to try on our side in order to get any further on this?

sipsorcery Jan 24, 2025
Maintainer

I'm struggling for ideas as well. It's very crude but what about putting a timer in your app and if the RTCPeerConnection isn't in a connected state after 10s then restart ICE and see if that does anyting.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Time out when negotiating connection #1256

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments 17 replies

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Time out when negotiating connection #1256

ppv-milestone Dec 11, 2024

Replies: 2 comments · 17 replies

sipsorcery Dec 14, 2024 Maintainer

sipsorcery Dec 27, 2024 Maintainer

ppv-milestone Jan 2, 2025 Author

ppv-milestone Jan 2, 2025 Author

sipsorcery Jan 2, 2025 Maintainer

ppv-milestone Jan 3, 2025 Author

sipsorcery Jan 3, 2025 Maintainer

ppv-milestone Jan 6, 2025 Author

sipsorcery Jan 6, 2025 Maintainer

ppv-milestone Jan 6, 2025 Author

ppv-milestone Jan 20, 2025 Author

sipsorcery Jan 24, 2025 Maintainer

ppv-milestone
Dec 11, 2024

Replies: 2 comments 17 replies

sipsorcery
Dec 14, 2024
Maintainer

sipsorcery Dec 27, 2024
Maintainer

ppv-milestone Jan 2, 2025
Author

ppv-milestone Jan 2, 2025
Author

sipsorcery Jan 2, 2025
Maintainer

ppv-milestone Jan 3, 2025
Author

sipsorcery
Jan 3, 2025
Maintainer

ppv-milestone Jan 6, 2025
Author

sipsorcery Jan 6, 2025
Maintainer

ppv-milestone Jan 6, 2025
Author

ppv-milestone Jan 20, 2025
Author

sipsorcery Jan 24, 2025
Maintainer