search

sipsorcery-org / sipsorcery

A WebRTC, SIP and VoIP library for C# and .NET. Designed for real-time communications apps.
https://sipsorcery-org.github.io/sipsorcery
Other
1.49k stars 442 forks source link

DTLS handshake failing #944

Closed WhiteOlivierus closed 10 months ago

WhiteOlivierus commented 1 year ago

I have been following this example. But I'm a little stuck. It seems to be that the DTLS handshake is having a timeout. I'm using STUNTMAN as STUN server. This is the out put when a connection is made.

stunserver.exe --verbosity 4
Starting server 1

strMode = <empty>
strPrimaryInterface = <empty>
strAltInterface = <empty>
strPrimaryAdvertised = <empty>
strAlternateAdvertised = <empty>
strPrimaryPort = <empty>
strAltPort = <empty>
strFamily = <empty>
strProtocol = <empty>
strHelp = <empty>
strVerbosity = 4
strMaxConnections = <empty>
strDosProtect = <empty>
strReuseAddr = <empty>

PP = 0.0.0.0:3478
Protocol = UDP
Configuring single threaded mode

Starting listener thread (1 recv sockets, 1 send sockets)Successfully started server.

recvfrom returns 20 from 127.0.0.1:57601 on local interface 127.0.0.1:3478
sendto returns 56 (err == 0)

And this is the output when WebRPC is trying to connect. 

[15:35:26 INF] WebRTC MP4 Source Demo
[15:35:26 INF] Starting web socket server...
02-06-2023 15:35:26|Warn |Logger.set_Level|The current logging level has been changed to Debug.
[15:35:26 INF] Waiting for web socket connections on 0.0.0.0:8081...
[15:35:26 INF] Press ctrl-c to exit.
02-06-2023 15:35:28|Debug|WebSocket.acceptHandshake|A handshake request from 127.0.0.1:63407:
                          GET / HTTP/1.1
                          Host: 127.0.0.1:8081
                          Connection: Upgrade
                          Pragma: no-cache
                          Cache-Control: no-cache
                          User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36
                          Upgrade: websocket
                          Origin: https://localhost:7030
                          Sec-WebSocket-Version: 13
                          Accept-Encoding: gzip, deflate, br
                          Accept-Language: en-US,en;q=0.9
                          Sec-WebSocket-Key: XwwIpOB7eoEicug56PV3MQ==
                          Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
02-06-2023 15:35:28|Debug|WebSocket.sendHttpResponse|A response to 127.0.0.1:63407:
                          HTTP/1.1 101 Switching Protocols
                          Server: websocket-sharp/1.0
                          Upgrade: websocket
                          Connection: Upgrade
                          Sec-WebSocket-Accept: LZNylMDiOjO4jBUU1SQxe43orjE=
                          Sec-WebSocket-Extensions: permessage-deflate; client_no_context_takeover; server_no_context_takeover
[15:35:28 DBG] Web socket client connection from 127.0.0.1:63407.
[15:35:28 WRN] No DTLS certificate is provided in the configuration
[15:35:28 DBG] CreateRtpSocket attempting to create and bind RTP socket(s) on [::]:0.
[15:35:28 DBG] CreateBoundSocket attempting to create and bind socket(s) on [::]:0 using protocol Udp.
[15:35:28 DBG] CreateBoundSocket successfully bound on [::]:62172, dual mode True.
[15:35:28 DBG] Successfully bound RTP socket [::]:62172 (dual mode True).
[15:35:28 DBG] RTPChannel for [::]:62172 started.
[15:35:28 DBG] SCTP windows size for data receiver set at 218.
[15:35:28 DBG] SCTP creating DTLS based association, is DTLS client False, ID 5000:5000:62172.
[15:35:28 INF] FFmpeg binaries found in: C:\apps\ffmpeg
[15:35:28 DBG] Adding ICE server for stun:localhost.
[15:35:28 INF] FFmpeg version info: 6.0-full_build-www.gyan.dev
[15:35:28 DBG] RTP ICE Channel discovered 1 local candidates.
[15:35:28 DBG] Adding ICE server for stun:localhost.
[15:35:28 DBG] Attempting to resolve STUN server URI stun:localhost.
[15:35:28 DBG] Sending SDP offer to client 127.0.0.1:63407.
[15:35:28 DBG] v=0
o=- 62736 0 IN IP4 127.0.0.1
s=sipsorcery
t=0 0
a=group:BUNDLE 0 1
m=audio 9 UDP/TLS/RTP/SAVP 0 101
c=IN IP4 0.0.0.0
a=ice-ufrag:KTRU
a=ice-pwd:ENGMMUXWSBGXORDTZFUJUWWP
a=fingerprint:sha-256 59:0F:05:69:F9:0B:AA:B1:F8:32:17:B0:56:A8:7B:8C:0A:78:35:E1:27:B9:8F:36:86:3B:C1:FE:7E:DB:91:7A
a=setup:actpass
a=candidate:1771851137 1 udp 2113937663 137.17.137.221 62172 typ host generation 0
a=ice-options:ice2,trickle
a=mid:0
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp-mux
a=rtcp:9 IN IP4 0.0.0.0
a=sendrecv
a=ssrc:1631269342 cname:fbd8a29d-acd9-4dc9-990c-dfb8092e2699
m=video 9 UDP/TLS/RTP/SAVP 96
c=IN IP4 0.0.0.0
a=ice-ufrag:KTRU
a=ice-pwd:ENGMMUXWSBGXORDTZFUJUWWP
a=fingerprint:sha-256 59:0F:05:69:F9:0B:AA:B1:F8:32:17:B0:56:A8:7B:8C:0A:78:35:E1:27:B9:8F:36:86:3B:C1:FE:7E:DB:91:7A
a=setup:actpass
a=ice-options:ice2,trickle
a=mid:1
a=rtpmap:96 VP8/90000
a=rtcp-mux
a=rtcp:9 IN IP4 0.0.0.0
a=sendrecv
a=ssrc:424658803 cname:2df0b403-5400-4423-bc15-597883e5a985

[15:35:29 DBG] ICE server stun:localhost successfully resolved to 127.0.0.1:3478.
[15:35:29 DBG] Sending STUN binding request to ICE server stun:localhost  with address 127.0.0.1:3478.
[15:35:29 DBG] STUN BindingSuccessResponse received from 127.0.0.1:3478.
[15:35:29 DBG] STUN binding success response received for ICE server check to stun:localhost.
[15:35:29 DBG] Adding server reflex ICE candidate for ICE server stun:localhost and 127.0.0.1:62172.
[15:35:29 DBG] STUN BindingRequest received from 137.17.137.221:62174.
[15:35:29 DBG] Adding peer reflex ICE candidate for 137.17.137.221:62174.
[15:35:29 DBG] Adding new candidate pair to checklist for: udp:[::]:62172 (host)->udp:137.17.137.221:62174 (prflx)
[15:35:29 DBG] Got remote SDP, type answer.
[15:35:29 WRN] DTLS packet received 157 bytes from [::ffff:137.17.137.221]:62174 but no DTLS transport available.
[15:35:29 DBG] Setting audio source format to 0:PCMU 8000.
[15:35:29 DBG] Setting audio source format to 0:PCMU 8000.
[h264 @ 000001f3fba91dc0] Reinit context to 1280x720, pix_fmt: yuv420p
[15:35:29 DBG] ICE RTP channel stopping ICE server checks in gathering state complete and connection state new.
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'C:\Projects\DHC\DHC.WebRTC\files\file_example.mp4':
  Metadata:
    major_brand     : mp42
    minor_version   : 0
    compatible_brands: mp42mp41isomavc1
    creation_time   : 2015-08-07T09:13:32.000000Z
  Duration: 00:00:30.53, start: 0.000000, bitrate: 2578 kb/s
  Stream #0:0[0x1](und): Video: h264 (High), 1 reference frame (avc1 / 0x31637661), yuv420p(tv, bt709, progressive, left), 1280x720 [SAR 1:1 DAR 16:9], 2453 kb/s, 30 fps, 30 tbr, 30 tbn (default)
    Metadata:
      creation_time   : 2015-08-07T09:13:32.000000Z
      handler_name    : L-SMASH Video Handler
      vendor_id       : [0][0][0][0]
      encoder         : AVC Coding
  Stream #0:1[0x2](und): Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, stereo, fltp, 160 kb/s (default)
    Metadata:
      creation_time   : 2015-08-07T09:13:32.000000Z
      handler_name    : L-SMASH Audio Handler
      vendor_id       : [0][0][0][0]
[15:35:29 DBG] FFmpeg file source decoder aac audio codec for stream 1.
[15:35:29 DBG] Setting video source format to 96:VP8 90000.
[15:35:29 DBG] Setting video source format to 96:VP8 90000.
[h264 @ 000001f3fbafb4c0] Reinit context to 1280x720, pix_fmt: yuv420p
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'C:\Projects\DHC\DHC.WebRTC\files\file_example.mp4':
  Metadata:
    major_brand     : mp42
    minor_version   : 0
    compatible_brands: mp42mp41isomavc1
    creation_time   : 2015-08-07T09:13:32.000000Z
  Duration: 00:00:30.53, start: 0.000000, bitrate: 2578 kb/s
  Stream #0:0[0x1](und): Video: h264 (High), 1 reference frame (avc1 / 0x31637661), yuv420p(tv, bt709, progressive, left), 1280x720 [SAR 1:1 DAR 16:9], 2453 kb/s[, 30 fps, 30 tbr, 15:35:2930 tbn (default)
    Metadata:
       creation_time   : 2015-08-07T09:13:32.000000Z
      handler_name    : DBGL-SMASH Video Handler
      vendor_id       : [0][0][0][0]]
      encoder         : AVC Coding
STUN   Stream #0:1[0x2](und): Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, stereo, fltp, 160 kb/sBindingRequest (default)
    Metadata:
      creation_time   :  received from 2015-08-07T09:13:32.000000Z
      handler_name    : L-SMASH Audio Handler
137.17.137.221:62174      vendor_id       : [0][0][0][0]
.
[15:35:29 DBG] FFmpeg file source decoder [h264] video codec for stream [0] - url:[C:\Projects\DHC\DHC.WebRTC\files\file_example.mp4].
[15:35:29 DBG] RTP ICE Channel remote credentials set.
[15:35:29 DBG] ICE connection state change to checking.
[15:35:29 DBG] SDP:[v=0
o=- 3932503458298617984 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0 1
a=msid-semantic: WMS
m=audio 9 UDP/TLS/RTP/SAVP 0 101
c=IN IP4 0.0.0.0
a=ice-ufrag:N/er
a=ice-pwd:Amgj798MASkfp1Z2o5gOZMB6
a=fingerprint:sha-256 D7:51:69:BF:01:49:22:03:F9:FC:E9:F2:DB:60:07:86:82:52:61:AF:C2:C5:19:C6:BF:76:D9:D8:1F:C7:4E:2C
a=setup:active
a=mid:0
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=rtcp:9 IN IP4 0.0.0.0
a=ice-options:trickle
a=rtcp-mux
a=recvonly
m=video 9 UDP/TLS/RTP/SAVP 96
c=IN IP4 0.0.0.0
a=ice-ufrag:N/er
a=ice-pwd:Amgj798MASkfp1Z2o5gOZMB6
a=fingerprint:sha-256 D7:51:69:BF:01:49:22:03:F9:FC:E9:F2:DB:60:07:86:82:52:61:AF:C2:C5:19:C6:BF:76:D9:D8:1F:C7:4E:2C
a=setup:active
a=mid:1
a=rtpmap:96 VP8/90000
a=rtcp:9 IN IP4 0.0.0.0
a=ice-options:trickle
a=rtcp-mux
a=recvonly
]
[15:35:29 DBG] LogRemoteSDPSsrcAttributes: Audio:[ ]
 Video: [  []  ]
[15:35:29 DBG] Got remote ICE candidate.
[15:35:29 DBG] ICE RTP channel sending connectivity check for udp:[::]:62172 (host)->udp:137.17.137.221:62174 (prflx) from [::]:62172 to 137.17.137.221:62174 (use candidate False).
[15:35:29 WRN] DTLS packet received 157 bytes from [::ffff:137.17.137.221]:62174 but no DTLS transport available.
[15:35:29 DBG] STUN BindingSuccessResponse received from 137.17.137.221:62174.
[15:35:29 DBG] ICE RTP channel binding response state Succeeded as Controller for udp:137.17.137.221:62174 (prflx)
[15:35:29 DBG] ICE RTP channel sending connectivity check for udp:[::]:62172 (host)->udp:137.17.137.221:62174 (prflx) from [::]:62172 to 137.17.137.221:62174 (use candidate True).
[15:35:29 DBG] STUN BindingSuccessResponse received from 137.17.137.221:62174.
[15:35:29 DBG] ICE RTP channel remote peer nominated entry from binding response udp:137.17.137.221:62174 (prflx)
[15:35:29 INF] ICE RTP channel connected after 187ms udp:[::]:62172 (host)->udp:137.17.137.221:62174 (prflx).
[15:35:29 DBG] ICE connection state change to connected.
[15:35:29 DBG] Peer connection state change to connecting.
[15:35:29 DBG] Peer connection closed with reason ice connected.
[15:35:29 DBG] RtpIceChannel for [::]:62172 closed.
[15:35:29 DBG] RTPChannel closing, RTP receiver on port 62172. Reason: ice connected.
[15:35:29 DBG] Peer connection state change to closed.
[15:35:29 DBG] Disposing of FFmpegAudioDecoder.
[AVIOContext @ 000001f3fba88ec0] Statistics: 410872 bytes read, 0 seeks
[15:35:29 DBG] Disposing of FFmpegVideoDecoder.
[AVIOContext @ 000001f3fc08c8c0] Statistics: 410872 bytes read, 0 seeks
[15:35:29 DBG] VideoEncoder dispose.
[15:35:29 INF] ICE connected to remote end point 137.17.137.221:62174.
[15:35:29 DBG] Starting DLS handshake with role passive.
[15:35:29 DBG] RTCPeerConnection DoDtlsHandshake started.
[15:35:29 DBG] DTLS commencing handshake as server.
[15:35:49 WRN] DTLS transport timed out after 20000ms waiting for handshake from remote client.
[15:35:49 WRN] DTLS server raised unexpected alert: fatal(2), internal_error(80).
[15:35:49 WRN] DTLS handshake as server timed out waiting for handshake to complete.
Org.BouncyCastle.Crypto.Tls.TlsFatalAlert: internal_error(80)
 ---> System.TimeoutException: The operation has timed out.
   at SIPSorcery.Net.DtlsSrtpTransport.Receive(Byte[] buf, Int32 off, Int32 len, Int32 waitMillis)
   at Org.BouncyCastle.Crypto.Tls.DtlsRecordLayer.ReceiveDatagram(Byte[] buf, Int32 off, Int32 len, Int32 waitMillis) in /_/crypto/src/crypto/tls/DtlsRecordLayer.cs:line 319
   at Org.BouncyCastle.Crypto.Tls.DtlsRecordLayer.ReceiveRecord(Byte[] buf, Int32 off, Int32 len, Int32 waitMillis) in /_/crypto/src/crypto/tls/DtlsRecordLayer.cs:line 529
   at Org.BouncyCastle.Crypto.Tls.DtlsRecordLayer.Receive(Byte[] buf, Int32 off, Int32 len, Int32 waitMillis) in /_/crypto/src/crypto/tls/DtlsRecordLayer.cs:line 175
   at Org.BouncyCastle.Crypto.Tls.DtlsReliableHandshake.ReceiveMessage() in /_/crypto/src/crypto/tls/DtlsReliableHandshake.cs:line 127
   at Org.BouncyCastle.Crypto.Tls.DtlsServerProtocol.ServerHandshake(ServerHandshakeState state, DtlsRecordLayer recordLayer) in /_/crypto/src/crypto/tls/DtlsServerProtocol.cs:line 88
   at Org.BouncyCastle.Crypto.Tls.DtlsServerProtocol.Accept(TlsServer server, DatagramTransport transport) in /_/crypto/src/crypto/tls/DtlsServerProtocol.cs:line 54
   --- End of inner exception stack trace ---
   at Org.BouncyCastle.Crypto.Tls.DtlsServerProtocol.Accept(TlsServer server, DatagramTransport transport) in /_/crypto/src/crypto/tls/DtlsServerProtocol.cs:line 69
   at SIPSorcery.Net.DtlsSrtpTransport.DoHandshakeAsServer(String& handshakeError)
[15:35:49 WRN] RTCPeerConnection DTLS handshake failed with error timeout.
[15:35:49 DBG] Peer connection state change to failed.

I have modified the code just a little bit, but not major enough that I thought there should be problems.

using System.Net;
using Microsoft.Extensions.Logging;
using ILogger = Microsoft.Extensions.Logging.ILogger;
using Microsoft.Extensions.Logging.Abstractions;
using Serilog;
using Serilog.Core;
using Serilog.Extensions.Logging;
using SIPSorcery.Media;
using SIPSorcery.Net;
using SIPSorceryMedia.Abstractions;
using SIPSorceryMedia.FFmpeg;
using WebSocketSharp.Server;
using SIPSorcery;
using Serilog.Events;
using System.Security.Cryptography.X509Certificates;
using System.Security.Authentication;

namespace DHC.WebRTC;

internal class Program
{
    private const string ffmpegLibFullPath = @"C:\apps\ffmpeg";
    private const string MP4_PATH = @"C:\Projects\DHC\DHC.WebRTC\files\file_example.mp4";
    private const string STUN_URL = "localhost";
    private const int WEBSOCKET_PORT = 8081;

    private static ILogger logger = NullLogger.Instance;

    private static void Main()
    {
        logger = AddConsoleLogger();

        logger.LogInformation("WebRTC MP4 Source Demo");

        logger.LogInformation("Starting web socket server...");
        WebSocketServer webSocketServer = new(IPAddress.Any, WEBSOCKET_PORT);

        webSocketServer.Log.Level = WebSocketSharp.LogLevel.Debug;
        webSocketServer.AddWebSocketService<WebRTCWebSocketPeer>("/", (peer) => peer.CreatePeerConnection = CreatePeerConnection);
        webSocketServer.Start();

        logger.LogInformation("Waiting for web socket connections on {Address}:{Port}...", webSocketServer.Address, webSocketServer.Port);
        logger.LogInformation("Press ctrl-c to exit.");

        ManualResetEvent exitMre = new(false);
        Console.CancelKeyPress += delegate (object? sender, ConsoleCancelEventArgs e)
        {
            e.Cancel = true;
            exitMre.Set();
        };

        exitMre.WaitOne();
    }

    private static Task<RTCPeerConnection> CreatePeerConnection()
    {
        RTCConfiguration config = new()
        {
            iceServers = new List<RTCIceServer>
            {
                new RTCIceServer
                {
                    urls = STUN_URL
                }
            }
        };

        RTCPeerConnection pc = new(config);

        FFmpegInit.Initialise(FfmpegLogLevelEnum.AV_LOG_VERBOSE, ffmpegLibFullPath, logger);
        FFmpegFileSource mediaFileSource = new(MP4_PATH, false, new AudioEncoder());
        mediaFileSource.RestrictFormats(x => x.Codec == VideoCodecsEnum.VP8);
        mediaFileSource.RestrictFormats(x => x.Codec == AudioCodecsEnum.PCMU);

        MediaStreamTrack videoTrack = new(mediaFileSource.GetVideoSourceFormats(), MediaStreamStatusEnum.SendRecv);
        pc.addTrack(videoTrack);
        MediaStreamTrack audioTrack = new(mediaFileSource.GetAudioSourceFormats(), MediaStreamStatusEnum.SendRecv);
        pc.addTrack(audioTrack);

        mediaFileSource.OnVideoSourceEncodedSample += pc.SendVideo;
        mediaFileSource.OnAudioSourceEncodedSample += pc.SendAudio;
        pc.OnVideoFormatsNegotiated += (videoFormats) => mediaFileSource.SetVideoSourceFormat(videoFormats.First());
        pc.OnAudioFormatsNegotiated += (audioFormats) => mediaFileSource.SetAudioSourceFormat(audioFormats.First());

        pc.onconnectionstatechange += async (state) =>
        {
            logger.LogDebug("Peer connection state change to {state}.", state);

            switch (state)
            {
                case RTCPeerConnectionState.failed:
                    pc.Close("ice disconnection");
                    break;

                case RTCPeerConnectionState.closed:
                    await mediaFileSource.CloseVideo();
                    break;

                case RTCPeerConnectionState.connected:
                    await mediaFileSource.StartVideo();
                    break;

                case RTCPeerConnectionState.disconnected:
                    pc.Close("ice disconnection");
                    break;

                case RTCPeerConnectionState.@new:
                    pc.Close("new ice connection");
                    break;

                case RTCPeerConnectionState.connecting:
                    pc.Close("ice connected");
                    break;

                default:
                    pc.Close("unknown state");
                    break;
            }
        };

        pc.OnReceiveReport += (re, media, rr) => logger.LogDebug("RTCP Receive for {media} from {re}\n{rr}", media, re, rr.GetDebugSummary());
        pc.OnSendReport += (media, sr) => logger.LogDebug("RTCP Send for {media}\n{sr}", media, sr.GetDebugSummary());
        pc.GetRtpChannel().OnStunMessageReceived += (msg, ep, isRelay) => logger.LogDebug("STUN {MessageType} received from {ep}.", msg.Header.MessageType, ep);
        pc.oniceconnectionstatechange += (state) => logger.LogDebug("ICE connection state change to {state}.", state);

        return Task.FromResult(pc);
    }

    private static ILogger AddConsoleLogger()
    {
        Logger seriLogger = new LoggerConfiguration()
            .Enrich.FromLogContext()
            .MinimumLevel.Is(LogEventLevel.Debug)
            .WriteTo.Console()
            .CreateLogger();
        SerilogLoggerFactory factory = new(seriLogger);
        LogFactory.Set(factory);
        return factory.CreateLogger<Program>();
    }
}

Can anyone give me a direction. I have been looking at this problem for over 2 days and no clue what should be done.

WhiteOlivierus commented 1 year ago

Even when using the STUNServer example, I get the same result.

WhiteOlivierus commented 1 year ago

Has no one any idea?

sipsorcery commented 10 months ago

Looks very much like a network connectivity problem. This in particular stun:localhost seems very weird. If you're running a STUN server on the same machine as your WebRTC peer it will be stuck behind the same NAT. Nomrally the STUN server would be on a public static IP address out on the Internet.

Feel free to re-open issue if ti's still relveant.