search

webrtc-rs / webrtc

A pure Rust implementation of WebRTC
https://webrtc.rs
Apache License 2.0
4.14k stars 368 forks source link

DTLS ServerKeyExchange failure #163

Open ghost opened 2 years ago

ghost commented 2 years ago

Could anyone help me out here? I am attempting to set up connectivity of a WebRTC-rs client DataChannel with https://github.com/naia-rs/naia-socket ... and it appears that the DTLS handshake is failing on the ServerKeyExchange message given, exactly here: https://github.com/webrtc-rs/dtls/blob/main/src/handshake/handshake_message_server_key_exchange.rs#L114 The message indicates that the incoming signature will be something like ~19000 bytes, but the incoming message size is only ~300 bytes ... curious.

The failing message is created/written by an openssl::SslAcceptor which is created here: https://github.com/kyren/webrtc-unreliable/blob/master/src/crypto.rs#L56

I have created an example repo to demonstrate this behavior here: https://github.com/naia-rs/naia-socket-webrtc-rs-example, you should be able to reproduce this pretty quite using this repo.

I suspect a DTLS version mismatch here? Does anyone know how I can check the version of DTLS being used to read/write messages in both openssl & webrtc-rs/dtls?

Thank you so much for any help!

webrtc-rs/dtls issue: https://github.com/webrtc-rs/dtls/issues/15 naia-socket issue: https://github.com/naia-rs/naia-socket/issues/56

mvlabat commented 2 years ago

Hi! I'm new to WebRTC. I tried reproducing the issue with the example you provided, but I got a different result. I can't see anything related to client: handshake parse failed: buffer is too small.

The error I'm getting instead: [2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1 result alert:Some(Alert { alert_level: Fatal, alert_description: InsufficientSecurity }), err:Some(ErrRequestedButNoSrtpExtension)

Is it possible that my system misses some kind of dependency? I'm not sure what srtp extension is. I get the same result on both MacOS and Arch Linux.

Server output:

$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.24s
     Running `/Users/mvlabat/rust/naia-socket-webrtc-rs-example/target/debug/naia-socket-server`
2022-04-29T10:01:25.628572Z INFO [naia_socket_server::app] Naia Server Socket Demo started
2022-04-29T10:01:25.749031Z INFO [webrtc_unreliable::server] new WebRTC data channel server listening on 127.0.0.1:14192, public addr 127.0.0.1:14192
2022-04-29T10:01:25.749247Z INFO [naia_server_socket::impls::webrtc::session] Session initiator available at POST http://127.0.0.1:14191/rtc_session
2022-04-29T10:01:31.00255Z INFO [naia_server_socket::impls::webrtc::session] Successful WebRTC session request from 127.0.0.1:14191
2022-04-29T10:01:31.002568Z INFO [webrtc_unreliable::server] session initiated with server user: 'EMbYFU4Il5CQ' and remote user: 'HOSTjrmOciTMfxxO'
2022-04-29T10:01:31.007098Z INFO [webrtc_unreliable::server] beginning client data channel connection with 192.168.1.173:64403
2022-04-29T10:01:31.051784Z WARN [webrtc_unreliable::client] SSL handshake failure with remote 192.168.1.173:64403: error:0A00042F:SSL routines:dtls1_read_bytes:tlsv1 alert insufficient security:ssl/record/rec_layer_d1.c:613:SSL alert number 71

Client output:

$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `/Users/mvlabat/rust/naia-socket-webrtc-rs-example/target/debug/webrtc-rs-client`
[2022-04-29T10:01:30Z INFO  webrtc_ice::mdns] mDNS is using 0.0.0.0:5353 as dest_addr
[2022-04-29T10:01:30Z TRACE webrtc_mdns::conn] Connected to interface address 127.0.0.1:0
[2022-04-29T10:01:30Z TRACE webrtc_mdns::conn] Connected to interface address 192.168.1.173:0
[2022-04-29T10:01:30Z TRACE mio::poll] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
[2022-04-29T10:01:30Z INFO  webrtc_mdns::conn] Looping and listening Ok(0.0.0.0:5353)
[2022-04-29T10:01:30Z TRACE webrtc_ice::agent::agent_internal] [controlled]: Set selected candidate pair: None
[2022-04-29T10:01:30Z INFO  webrtc::peer_connection] signaling state changed to have-local-offer
[2022-04-29T10:01:30Z TRACE mio::poll] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
[2022-04-29T10:01:30Z TRACE mio::poll] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE
received ice candidate from: 192.168.1.173
[2022-04-29T10:01:30Z WARN  webrtc_ice::agent::agent_gather] [controlled]: could not listen udp fe:80::: io error: Can't assign requested address (os error 49)
received ice candidate from: ::
[2022-04-29T10:01:31Z DEBUG reqwest::connect] starting new connection: http://127.0.0.1:14191/
[2022-04-29T10:01:31Z TRACE mio::poll] registering event source with poller: token=Token(4), interests=READABLE | WRITABLE
[2022-04-29T10:01:31Z TRACE want] signal: Want
[2022-04-29T10:01:31Z TRACE want] signal found waiting giver, notifying
[2022-04-29T10:01:31Z TRACE want] poll_want: taker wants!
[2022-04-29T10:01:31Z DEBUG reqwest::async_impl::client] response '200 OK' for http://127.0.0.1:14191/rtc_session
[2022-04-29T10:01:31Z TRACE mio::poll] deregistering event source from poller
[2022-04-29T10:01:31Z TRACE want] signal: Closed
[2022-04-29T10:01:31Z TRACE want] signal found waiting giver, notifying
[2022-04-29T10:01:31Z TRACE want] poll_want: closed
[2022-04-29T10:01:31Z INFO  webrtc::peer_connection] signaling state changed to stable
[2022-04-29T10:01:31Z TRACE webrtc::peer_connection] start_transports: ice_role=controlling, dtls_role=server
[2022-04-29T10:01:31Z DEBUG webrtc_ice::agent::agent_internal] Started agent: isControlling? true, remoteUfrag: EMbYFU4Il5CQ, remotePwd: LoBhv6zv3UAkVBjt4TINBzin
[2022-04-29T10:01:31Z INFO  webrtc_ice::agent::agent_internal] [controlling]: Setting new connection state: Checking
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_internal] [controlling]: pinging all candidates
[2022-04-29T10:01:31Z INFO  webrtc::peer_connection] ICE connection state changed: checking
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_internal] [controlling]: ping STUN from udp4 host 192.168.1.173:64403 to udp4 host 127.0.0.1:14192
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] inbound STUN (SuccessResponse) from udp4 host 127.0.0.1:14192 to udp4 host 192.168.1.173:64403
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] Found valid candidate pair: prio 7755113473190677858 (local, prio 2130706431) udp4 host 192.168.1.173:64403 <-> udp4 host 127.0.0.1:14192 (remote, prio 1805628061), p.state: 4, isUseCandidate: false, true
[2022-04-29T10:01:31Z WARN  webrtc_ice::agent::agent_gather] [controlling]: failed to resolve stun host: stun.l.google.com:19302: io error: No available ipv6 IP address found!
[2022-04-29T10:01:31Z TRACE mio::poll] registering event source with poller: token=Token(16777220), interests=READABLE | WRITABLE
received ice candidate from: 176.37.83.37
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] Nominatable pair found, nominating (udp4 host 192.168.1.173:64403, udp4 host 127.0.0.1:14192)
all local candidates received
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] ping STUN (nominate candidate pair from udp4 host 192.168.1.173:64403 to udp4 host 127.0.0.1:14192
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_internal] [controlling]: ping STUN from udp4 host 192.168.1.173:64403 to udp4 host 127.0.0.1:14192
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] inbound STUN (SuccessResponse) from udp4 host 127.0.0.1:14192 to udp4 host 192.168.1.173:64403
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] Found valid candidate pair: prio 7755113473190677858 (local, prio 2130706431) udp4 host 192.168.1.173:64403 <-> udp4 host 127.0.0.1:14192 (remote, prio 1805628061), p.state: 4, isUseCandidate: true, true
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_internal] [controlling]: Set selected candidate pair: Some(prio 7755113473190677858 (local, prio 2130706431) udp4 host 192.168.1.173:64403 <-> udp4 host 127.0.0.1:14192 (remote, prio 1805628061))
[2022-04-29T10:01:31Z INFO  webrtc_ice::agent::agent_internal] [controlling]: Setting new connection state: Connected
[2022-04-29T10:01:31Z INFO  webrtc::peer_connection] ICE connection state changed: connected
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1: Preparing
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1: Sending
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] Send [handshake:client] -> ClientHello (epoch: 0, seq: 0)
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1: Waiting
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] Recv [handshake:client] -> ServerHello (epoch: 0, seq: 0)
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1 result alert:None, err:None
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1 result alert:None, err:None
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1 result alert:None, err:None
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] Recv [handshake:client] -> Certificate (epoch: 0, seq: 1)
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1 result alert:None, err:None
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] Recv [handshake:client] -> ServerKeyExchange (epoch: 0, seq: 2)
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] Recv [handshake:client] -> ServerHelloDone (epoch: 0, seq: 3)
[2022-04-29T10:01:31Z TRACE webrtc_dtls::handshaker] [handshake:client] Flight 1 result alert:Some(Alert { alert_level: Fatal, alert_description: InsufficientSecurity }), err:Some(ErrRequestedButNoSrtpExtension)
[2022-04-29T10:01:31Z INFO  webrtc::peer_connection] peer connection state changed: failed
[2022-04-29T10:01:31Z WARN  webrtc::peer_connection::peer_connection_internal] Failed to start manager dtls: SRTP support was requested but server did not respond with use_srtp extension
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] client: read_and_buffer exit
[2022-04-29T10:01:31Z WARN  webrtc::peer_connection::peer_connection_internal] Failed to start SCTP: DTLS not established
[2022-04-29T10:01:31Z TRACE webrtc_dtls::conn] client: handle_outgoing_packets exit
[2022-04-29T10:01:31Z WARN  webrtc::peer_connection::peer_connection_internal] undeclared_media_processor failed to open SrtcpSession
[2022-04-29T10:01:31Z WARN  webrtc::peer_connection::peer_connection_internal] undeclared_media_processor failed to open SrtpSession
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] [controlling]: checking keepalive
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] [controlling]: checking keepalive
[2022-04-29T10:01:31Z TRACE webrtc_ice::agent::agent_selector] [controlling]: checking keepalive
...