centricular / gstwebrtc-demos

Superseded by https://gitlab.freedesktop.org/gstreamer/gstreamer/-/tree/main/subprojects/gst-examples/webrtc - Demo apps for using gstreamer's webrtc implementation
https://gitlab.freedesktop.org/gstreamer/gstreamer/-/tree/main/subprojects/gst-examples/webrtc
BSD 2-Clause "Simplified" License
490 stars 197 forks source link

DTLS error and no response from gstreamer client #66

Closed tobiasfriden closed 5 years ago

tobiasfriden commented 5 years ago

Hello,

I am trying to stream video from a gstreamer-webrtc based client to a golang SFU that I have implemented.

I have an issue where the ice connection state never changes from "checking", and after doing some whireshark dumps I seem to have found the root case: When the server sends a "DTLS client hello", the gstreamer client does not respond. The server tries to send client hello some more times and finally fails with a Reassembly Error.

When I instead use a browser client with the standard javascript-API, the browser client responds to the "DTLS client hello" with "DTLS server hello", followed by certificate exchange.

Also, it seems like the browser client is using DTLSv1.2 while gstreamer is using DTLSv1.0.

ystreet commented 5 years ago

Are you completely sure that an ICE connection is correctly negotiated and set up? Are you sure that the gstreamer client receives the DTLS client hello from the server? Are your a=setup: lines correct for the server initiating the hello?

tobiasfriden commented 5 years ago

I get several STUN "binding success response" so I would assume that means that the ICE connection is setup correctly? I only get a=setup:active from the server, don't know if that is correct or not.

ystreet commented 5 years ago

STUN "binding success response" from where? gstreamer or server? Even then that's half the setup, then the peer would attempt to connect to that port which may or may not succeed. It sounds like you may need to look into libnice debugging or trying libnice master.

a=setup:active is fine in all cases (either side creating the offer however JSEP would like the offerer to initiate with actpass).

tobiasfriden commented 5 years ago

Ok so after some more whiresharking, it seems like the server sends the STUN "binding request" and gstreamer responds with "binding success response". Also the DTLS client hello is recieved by gstreamer.

Any pointers to how to debug libnice? I tried setting G_MESSAGES_DEBUG=all and there is a lot of output about STUN messages but nothing about any DTLS errors.

ystreet commented 5 years ago

dtls is in GST_DEBUG=*dtls*:6 logs. If that indicates that the hello was received then ice is fine.

tobiasfriden commented 5 years ago

Seems to be some kind of error during the handshake:

0:00:00.831074100    33      0x16aaa80 DEBUG                dtlsenc gstdtlsenc.c:330:gst_dtls_enc_change_state:<dtlsenc0> starting connection rtp_0_2764744914
0:00:00.833465000    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f36e802d2f0> initial state set: role=serverbuf=((nil):0/0) 10110|0 before SSL initialization
0:00:00.842894100    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f36e802d2f0> poll: before handshake: role=server buf=((nil):0/0) 10110|0 before SSL initialization
0:00:00.842950700    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:977:bio_method_ctrl:<GstDtlsConnection@0x7f36e802d2f0> BIO: unhandled ctrl, 6
0:00:00.842976900    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:903:bio_method_read:<GstDtlsConnection@0x7f36e802d2f0> BIO: EOF
0:00:00.860378200    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f36e802d2f0> poll: after handshake: role=server buf=((nil):0/0) 1010010|0 before SSL initialization
0:00:00.860433800    33      0x16aaa80 WARN          dtlsconnection gstdtlsconnection.c:737:openssl_poll:<GstDtlsConnection@0x7f36e802d2f0> do_handshake encountered BIO error
0:00:00.863217200    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:760:openssl_poll:<GstDtlsConnection@0x7f36e802d2f0> SSL syscall (error) : 0
0:00:00.863341300    33      0x16aaa80 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f36e802d2f0> first poll done: role=server buf=((nil):0/0) 1010010|0 before SSL initialization
ystreet commented 5 years ago

BIO errors are normal when initializing.

tobiasfriden commented 5 years ago

From what I can see in the debug log and wireshark its still the same:

0:01:24.910546200    58 0x7f9318004e30 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f934402cbf0> handling timeout before poll: role=server buf=((nil):293/293) 10010|1a SSLv3/TLS write server done
0:01:24.910597500    58 0x7f9318004e30 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f934402cbf0> poll: before handshake: role=server buf=((nil):293/293) 10010|1a SSLv3/TLS write server done
0:01:24.910684000    58 0x7f9318004e30 LOG           dtlsconnection gstdtlsconnection.c:903:bio_method_read:<GstDtlsConnection@0x7f934402cbf0> BIO: EOF
0:01:24.910712900    58 0x7f9318004e30 LOG           dtlsconnection gstdtlsconnection.c:625:log_state:<GstDtlsConnection@0x7f934402cbf0> poll: after handshake: role=server buf=((nil):293/293) 1010010|1a SSLv3/TLS write server done
0:01:24.910817400    58 0x7f9318004e30 WARN          dtlsconnection gstdtlsconnection.c:737:openssl_poll:<GstDtlsConnection@0x7f934402cbf0> do_handshake encountered BIO error
0:01:24.910838200    58 0x7f9318004e30 LOG           dtlsconnection gstdtlsconnection.c:760:openssl_poll:<GstDtlsConnection@0x7f934402cbf0> SSL syscall (error) : 0

when trying to do the handshake, and no response from the gstreamer client on the client handshake attempt. Everytime it tries do do_handshake there is a BIO error, is that normal?

ystreet commented 5 years ago

The BIO: EOF error is normal yes.

petergerten commented 5 years ago

I am running into the same errors here https://github.com/centricular/gstwebrtc-demos/issues/78 Furthermore I don't see any DTLS packets on the wire despite all the dtls debug output: https://pastebin.com/dHa8sfLw

saket424 commented 5 years ago

@tobiasfriden

These three gists from you helped me a lot to get gstreamer webrtcbin sendrecv working with Janus SFU.

https://gist.github.com/tobiasfriden/f30dbddc76d5d42af28c997f04042cff

https://gist.github.com/tobiasfriden/3359c9a125c726d9c134359507d3450a

https://gist.github.com/tobiasfriden/ebccbe35c94b2c8d507922e0edf7bbba

Many Thanks!

The problems in this issue appear to be with a different go lang based SFU and not janus.

@petergerten Your hint in https://github.com/centricular/gstwebrtc-demos/issues/78 led me to get past the last issue I had. Thanks

tobiasfriden commented 5 years ago

@saket424 great news, glad it helped!

Did you change anything in the code to get it working? Would you mind sharing your modifications in that case?

saket424 commented 5 years ago

I am a python and gstreamer newbie I took your above gists as a basis to modify the sendrecv python sample to use Janus as the signaling server instead of nirbheek's

The one line that I added as mentioned in issue #78 is

self.webrtc.emit('add-ice-candidate', mlineindex, candidate)

If you promise not to laugh, I can post my hacked up (but functioning) copy as a gist and you can clean it up and make it a gst-webrtcbinsendcv-janus.py example similar to what the aiortc+janus.py gist example that you so ably made.

saket424 commented 5 years ago

@ystreet & @MathieuDuponchelle In the sdp answer from janus, the full list of ice_candidates are included as part of the sdp itself and they do not trickle in. Do the sendrecv gst samples parse the sdp and those remote ice candidates automatically or is there a function to parse those and add them explicitly. It would make sense if they can be added automatically when the remote sdp is parsed .

I have a case now where my code sample works when both the local and remote ice candidates happen to be on the same subnet and fails because no DTLS exchange is initiated when the local and candidate pairs are not on the same subnet

saket424 commented 5 years ago

Here is what a sample remote answer from janus looks like. Notice the remote candidate list is part of the sdp answer

plugin='janus.plugin.videoroom', data={'videoroom': 'event', 'room': 1234, 'configured': 'ok', 'video_codec': 'h264'}, jsep={'type': 'answer', 'sdp': 'v=0\r\no=- 1550598875962094 1 IN IP4 18.20.154.54\r\ns=VideoRoom 1234\r\nt=0 0\r\na=group:BUNDLE video0\r\na=msid-semantic: WMS janus\r\na=ice-lite\r\nm=video 9 UDP/TLS/RTP/SAVPF 97\r\nc=IN IP4 18.20.154.54\r\na=recvonly\r\na=mid:video0\r\na=rtcp-mux\r\na=ice-ufrag:k/pm\r\na=ice-pwd:Yv8xdlLBBPDsH8xNtU4RlC\r\na=ice-options:trickle\r\na=fingerprint:sha-256 5A:87:EA:BC:F8:55:06:D5:B3:9D:52:1C:78:F9:51:D9:9A:F1:71:21:05:CA:20:4B:67:EF:3A:90:78:06:55:8E\r\na=setup:active\r\na=rtpmap:97 H264/90000\r\na=fmtp:97 profile-level-id=42e01f;packetization-mode=1\r\na=rtcp-fb:97 ccm fir\r\na=rtcp-fb:97 nack\r\na=rtcp-fb:97 nack pli\r\na=rtcp-fb:97 goog-remb\r\na=rtcp-fb:97 transport-cc\r\na=candidate:1 1 udp 2013266431 18.20.154.54 58098 typ host\r\na=candidate:2 1 tcp 1015022079 18.20.154.54 0 typ host tcptype active\r\na=candidate:3 1 tcp 1010827775 18.20.154.54 42394 typ host tcptype passive\r\na=end-of-candidates\r\n'}

ystreet commented 5 years ago

webrtcbin currently does not parse ice candidates from the sdp. Patches to fix this are welcome :)

saket424 commented 5 years ago

@ystreet Thanks for the response. I will look into submitting a patch to the underlying C code to parse candidates included in the sdp. What puzzled me was that when the Janus server was on the same LAN as the gstwebrtc-sendrecv publisher, webrtc got negotiated and media was flowing. I would not have expected even this corner case to succeed since all the remote candidates are specified in the sdp and never via trickle.

saket424 commented 5 years ago

@ystreet I came up with a janus workaround. There is a flag in janus called full_trickle = true in the [nat] section of janus.cfg. When this is set, it sends all its candidates as "trickle" instead of as part of the answer. I modified the sendrecv python sample to process these trickle remote candidates and now yes I do have video even when the janus server is not on the same subnet

jacardre commented 5 years ago

@saket424 Hello, could you share your modified sendrecv python implementation to talk to Janus? I've been trying to run the examples with Janus as the signalling server but can't even successfully connect to the WebSocket server. I modified the WebSocket connection to add the sub-protocol 'janus-protocol' as stated in the Janus API but there are other protocol failures and it seems that your workarounds are simpler.

jmorgade commented 5 years ago

Hi all,

I am using the gstwebrtc-demos as a basis to build a C source based gstreamer client to interact with janus gw. I took the original webrtc-sendrecv.c source and have implemented all janus signaling stuff on top of it. So far, everything works really well whenever both janus and webrtc-sendrecv.c run over the same subnet. However, I am facing some issues with gstreamer if I setup janus i.e in a different network while everything looks fine with the regular janus java scripts demo samples (janus.js) so it doesn't look like a problem with janus itself.

Looking at your posts looks you were facing similar issues. Hence I was wondering if someone managed to get running the C sample with Janus as well (on the different nets).

I am trying to debug in deep what's going on and looks that whenever I run everything on the same subnet ... is janus the one who starts the dtls handshake, on the other hand when both run on different nets (i.e janus in AWS) no dtls negotiation starts.

Moreover, I noticed that the SDP answer is slightly different with additional tags a=srss (running janus in AWS) so I was wondering whether that could be also a reason.

I can share some logs if someone is happy to help.

Javier

ystreet commented 5 years ago

The original issue seems to have been user error with ICE candidates not being trickled to webrtcbin (instead being stored in the SDP which webrtcbin does not read for candidates).

If you have another problem, please open another issue.

saket424 commented 5 years ago

@tobiasfriden

I have created a gist with my functioning code for your reference borrowing from your gist

https://gist.github.com/saket424/4920977cebaf49ab17c64a1162578eed

I am giving a talk at JanusCon next week on gstreamer webrtcbin and it's applicability to janus plugins

thaytan commented 5 years ago

Would you be open to releasing the Janus example under the BSD 2-Clause license and us integrating it into the repo?

saket424 commented 5 years ago

I am open if @tobiasfriden is since I used his code as a starting point

tobiasfriden commented 5 years ago

@saket424 @thaytan sure!

saket424 commented 4 years ago

@thaytan , By default, janus includes the ice candidates in the sdp and does not trickle them unless full_trickle = "true" in the [nat] section of janus.cfg

I have modified the janusvideoroom.py client gist to parse the remote ice-candidates either from the SDP if they exist there(which they do by default) or from the trickle messages from janus (if full_trickle is set)

thaytan commented 4 years ago

I pushed a patch to GStreamer to parse ICE candidates from the SDP yesterday, so that problem will disappear in a future release. Do you have the python code for the app workaround handy?

saket424 commented 4 years ago

@thaytan
Line 333 of my gist file https://gist.github.com/saket424/4920977cebaf49ab17c64a1162578eed parses the candidates if they arrive in the sdp

        for line in sdp.splitlines():
            if line.startswith("a=candidate"):
                candidate = line[2:]
                print ('Received remote ice-candidate : %s\n' % candidate)
                self.webrtc.emit('add-ice-candidate', 0, candidate)
thaytan commented 4 years ago

Thanks. That's not quite right because it hard codes 0 for the mlineindex. It will work if all streams are bundled, but not in the general case.

thaytan commented 4 years ago

I pushed the Janus example with some modifications to https://github.com/centricular/gstwebrtc-demos/blob/master/janus/janusvideoroom.py Thanks!

tobiasfriden commented 4 years ago

@saket424 just saw your presentation from JanusCon (on youtube), great stuff! Really good summary. Was wondering if it is possible to find your presentation somewhere, or if you otherwise might mail it to me? If so my email is tobias@airpelago.com. Thanks!

thaytan commented 4 years ago

Got a link to the Youtube video?

saket424 commented 4 years ago

https://www.januscon.it/slides/AnandSetlur-JanusCon.pdf https://www.youtube.com/watch?v=RbA7kKc5I4g

thaytan commented 4 years ago

Thanks!

arpu commented 4 years ago

would it be possible to upload the pdf again? maybe elsewhere? @saket424 i get 404

sampleref commented 4 years ago

I am facing issue where webrtcbin acting as video receiver is not initiating dtls handshake.

Using GStreamer 1.16 on Ubuntu 16.04. The sdp is sent from browser as sendonly and its only SDP, no ICE within. All ICE is coming up as trickle. Gstreamer logs as below,

_0:01:19.248821190 19 0x7f3d34002ca0 DEBUG dtlsdec gstdtlsdec.c:595:get_agent_by_pem: no agent with generated cert found, creating new 0:01:19.249210492 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1020:bio_method_new: BIO: new 0:01:19.249251780 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d3404cb00 connection created: role=server buf=((nil):0/0) 10110|0 before SSL initialization 0:01:19.249468775 19 0x7f3d34002ca0 DEBUG dtlsdec gstdtlsdec.c:599:get_agent_by_pem:GstDtlsAgent@0x7f3d20019970 using agent with generated cert 0:01:19.249571638 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1020:bio_method_new: BIO: new 0:01:19.249592799 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d20047d70 connection created: role=server buf=((nil):0/0) 10110|0 before SSL initialization 0:01:19.250192175 19 0x7f3d34002ca0 DEBUG dtlssrtpenc gstdtlssrtpenc.c:329:gst_dtls_srtp_enc_request_new_pad: pad requested 0:01:19.250296352 19 0x7f3d34002ca0 LOG dtlssrtpenc gstdtlssrtpenc.c:347:gst_dtls_srtp_enc_request_new_pad: added rtp sink pad 0:01:19.250325347 19 0x7f3d34002ca0 DEBUG dtlssrtpenc gstdtlssrtpenc.c:329:gst_dtls_srtp_enc_request_new_pad: pad requested 0:01:19.250414248 19 0x7f3d34002ca0 LOG dtlssrtpenc gstdtlssrtpenc.c:362:gst_dtls_srtp_enc_request_new_pad: added rtcp sink pad 0:01:19.250455687 19 0x7f3d34002ca0 DEBUG dtlssrtpenc gstdtlssrtpenc.c:329:gst_dtls_srtp_enc_request_new_pad: pad requested 0:01:19.250468782 19 0x7f3d34002ca0 DEBUG dtlsenc gstdtlsenc.c:347:gst_dtls_enc_request_new_pad: sink pad requested 0:01:19.250521012 19 0x7f3d34002ca0 LOG dtlssrtpenc gstdtlssrtpenc.c:369:gst_dtls_srtp_enc_request_new_pad: added data sink pad 0:01:19.250588258 19 0x7f3d34002ca0 DEBUG dtlssrtpenc gstdtlssrtpenc.c:329:gst_dtls_srtp_enc_request_new_pad: pad requested 0:01:19.250666029 19 0x7f3d34002ca0 LOG dtlssrtpenc gstdtlssrtpenc.c:362:gst_dtls_srtp_enc_request_new_pad: added rtcp sink pad 0:01:19.251023764 19 0x7f3d34002ca0 DEBUG dtlssrtpdec gstdtlssrtpdec.c:285:gst_dtls_srtp_dec_request_new_pad: pad requested 0:01:19.251037189 19 0x7f3d34002ca0 DEBUG dtlsdec gstdtlsdec.c:360:gst_dtls_dec_request_new_pad: requesting pad 0:01:19.251077102 19 0x7f3d34002ca0 LOG dtlssrtpdec gstdtlssrtpdec.c:304:gst_dtls_srtp_dec_request_new_pad: added data src pad 0:01:19.251110708 19 0x7f3d34002ca0 DEBUG dtlssrtpdec gstdtlssrtpdec.c:285:gst_dtls_srtp_dec_request_new_pad: pad requested 0:01:19.251123030 19 0x7f3d34002ca0 DEBUG dtlsdec gstdtlsdec.c:360:gst_dtls_dec_request_new_pad: requesting pad 0:01:19.251163124 19 0x7f3d34002ca0 LOG dtlssrtpdec gstdtlssrtpdec.c:304:gst_dtls_srtp_dec_request_new_pad: added data src pad 0:01:19.252112090 19 0x7f3d200196d0 FIXME default gstutils.c:3981:gst_pad_create_stream_id_internal: Creating random stream-id, consider implementing a deterministic way of creating a stream-id 0:01:19.252142638 19 0x7f3d200196d0 WARN GST_PADS gstpad.c:4230:gst_pad_peer_query: could not send sticky events 0:01:19.252241508 19 0x7f3d200730f0 FIXME default gstutils.c:3981:gst_pad_create_stream_id_internal: Creating random stream-id, consider implementing a deterministic way of creating a stream-id 0:01:19.252284122 19 0x7f3d200730f0 WARN GST_PADS gstpad.c:4230:gst_pad_peer_query: could not send sticky events 0:01:19.818888078 19 0x7f3d34002ca0 DEBUG dtlsdec gstdtlsdec.c:658:gst_dtls_dec_fetch_connection: fetching 'rtp_0_1672472566' from connection table, size is 2 0:01:19.818919615 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:496:gst_dtls_connection_set_send_callback:GstDtlsConnection@0x7f3d3404cb00 locking @ set_send_callback 0:01:19.818950233 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:498:gst_dtls_connection_set_send_callback:GstDtlsConnection@0x7f3d3404cb00 locked @ set_send_callback 0:01:19.818964403 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:510:gst_dtls_connection_set_send_callback:GstDtlsConnection@0x7f3d3404cb00 unlocking @ set_send_callback 0:01:19.819047033 19 0x7f3d34002ca0 DEBUG dtlsenc gstdtlsenc.c:378:src_activate_mode: src pad activating in push mode 0:01:19.819114275 19 0x7f3d34002ca0 DEBUG dtlsenc gstdtlsenc.c:330:gst_dtls_enc_change_state: starting connection rtp_0_1672472566 0:01:19.819129207 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:303:gst_dtls_connection_start:GstDtlsConnection@0x7f3d3404cb00 locking @ start 0:01:19.819141912 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:305:gst_dtls_connection_start:GstDtlsConnection@0x7f3d3404cb00 locked @ start 0:01:19.819159030 19 0x7f3d200fb320 TRACE dtlsenc gstdtlsenc.c:414:src_task_loop: src loop: acquiring lock 0:01:19.819162363 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d3404cb00 initial state set: role=client buf=((nil):0/0) 1110|0 before SSL initialization 0:01:19.819186832 19 0x7f3d200fb320 TRACE dtlsenc gstdtlsenc.c:416:src_task_loop: src loop: acquired lock 0:01:19.819225485 19 0x7f3d200fb320 TRACE dtlsenc gstdtlsenc.c:426:src_task_loop: src loop: queue empty, waiting for add 0:01:19.819211576 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d3404cb00 poll: before handshake: role=client buf=((nil):0/0) 1110|0 before SSL initialization 0:01:19.819339512 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: unhandled ctrl, 6 0:01:19.819403512 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:980:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: Timeout set 0:01:19.819422778 19 0x7f3d34002ca0 DEBUG dtlsconnection gstdtlsconnection.c:390:gst_dtls_connection_check_timeout_locked:GstDtlsConnection@0x7f3d3404cb00 waiting for 999981 usec 0:01:19.819495301 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: unhandled ctrl, 49 0:01:19.819506492 19 0x7f3d34002ca0 DEBUG dtlsconnection gstdtlsconnection.c:1006:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: MTU query, returning 0... 0:01:19.819516489 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: unhandled ctrl, 49 0:01:19.819527594 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: unhandled ctrl, 49 0:01:19.819538094 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: unhandled ctrl, 42 0:01:19.819556173 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d3404cb00 BIO: unhandled ctrl, 49

0:01:19.819987805 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d3404cb00 poll: after handshake: role=client buf=((nil):0/0) 1001010|c SSLv3/TLS write client hello 0:01:19.820002220 19 0x7f3d34002ca0 DEBUG dtlsconnection gstdtlsconnection.c:758:openssl_poll:GstDtlsConnection@0x7f3d3404cb00 do_handshake encountered BIO error 0:01:19.820023588 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:793:openssl_poll:GstDtlsConnection@0x7f3d3404cb00 SSL syscall error: errno 0: Success 0:01:19.820039250 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d3404cb00 first poll done: role=client buf=((nil):0/0) 1001010|c SSLv3/TLS write client hello 0:01:19.820053051 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:325:gst_dtls_connection_start:GstDtlsConnection@0x7f3d3404cb00 unlocking @ start 0:01:19.820211876 19 0x7f3d34002ca0 DEBUG dtlsdec gstdtlsdec.c:658:gst_dtls_dec_fetch_connection: fetching 'rtcp_0_1115281242' from connection table, size is 1 0:01:19.820230701 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:496:gst_dtls_connection_set_send_callback:GstDtlsConnection@0x7f3d20047d70 locking @ set_send_callback 0:01:19.820244661 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:498:gst_dtls_connection_set_send_callback:GstDtlsConnection@0x7f3d20047d70 locked @ set_send_callback 0:01:19.820257349 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:510:gst_dtls_connection_set_send_callback:GstDtlsConnection@0x7f3d20047d70 unlocking @ set_send_callback 0:01:19.820338526 19 0x7f3d34002ca0 DEBUG dtlsenc gstdtlsenc.c:378:src_activate_mode: src pad activating in push mode 0:01:19.820399376 19 0x7f3d34002ca0 DEBUG dtlsenc gstdtlsenc.c:330:gst_dtls_enc_change_state: starting connection rtcp_0_1115281242 0:01:19.820411636 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:303:gst_dtls_connection_start:GstDtlsConnection@0x7f3d20047d70 locking @ start 0:01:19.820421325 19 0x7f3d34002ca0 TRACE dtlsconnection gstdtlsconnection.c:305:gst_dtls_connection_start:GstDtlsConnection@0x7f3d20047d70 locked @ start 0:01:19.820430493 19 0x7f3d200fc800 TRACE dtlsenc gstdtlsenc.c:414:src_task_loop: src loop: acquiring lock 0:01:19.820448016 19 0x7f3d200fc800 TRACE dtlsenc gstdtlsenc.c:416:src_task_loop: src loop: acquired lock 0:01:19.820435910 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d20047d70 initial state set: role=client buf=((nil):0/0) 1110|0 before SSL initialization 0:01:19.820482086 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:629:log_state:GstDtlsConnection@0x7f3d20047d70 poll: before handshake: role=client buf=((nil):0/0) 1110|0 before SSL initialization 0:01:19.820525455 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:1012:bio_method_ctrl:GstDtlsConnection@0x7f3d20047d70 BIO: unhandled ctrl, 6 0:01:19.820570160 19 0x7f3d34002ca0 LOG dtlsconnection gstdtlsconnection.c:980:bio_methodctrl:GstDtlsConnection@0x7f3d20047d70 BIO: Timeout set

Looks like its trying to send client hello but not succeeded. No DTLS packets on wireshark sent. And I verified that no ICE messages are within SDP offer. SDP offer to gstreamer webrtcbin as below,

"sdp":"v=0\r\no=- 8360833541034081384 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=msid-semantic: WMS bq1tGSK02H1PuMDFtTllrvRqC9dXWTgLyFCB\r\nm=video 9 UDP/TLS/RTP/SAVPF 96 97 98 99 100 101 102 122 127 121 125 107 108 109 124 120 123\r\nc=IN IP4 0.0.0.0\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=ice-ufrag:r7ot\r\na=ice-pwd:Odrs9UUbWfEdJ+Q1iKO/WyQQ\r\na=ice-options:trickle\r\na=fingerprint:sha-256 FD:D2:FC:22:F2:FB:1A:2A:57:35:6D:3B:07:05:0A:EC:3E:3B:EC:60:72:10:67:4F:1B:71:AB:5B:2D:C1:A7:4D\r\na=setup:actpass\r\na=mid:0\r\na=extmap:14 urn:ietf:params:rtp-hdrext:toffset\r\na=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=extmap:13 urn:3gpp:video-orientation\r\na=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:12 http://www.webrtc.org/experiments/rtp-hdrext/playout-delay\r\na=extmap:11 http://www.webrtc.org/experiments/rtp-hdrext/video-content-type\r\na=extmap:7 http://www.webrtc.org/experiments/rtp-hdrext/video-timing\r\na=extmap:8 http://tools.ietf.org/html/draft-ietf-avtext-framemarking-07\r\na=extmap:9 http://www.webrtc.org/experiments/rtp-hdrext/color-space\r\na=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\na=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\na=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\na=sendonly\r\na=msid:bq1tGSK02H1PuMDFtTllrvRqC9dXWTgLyFCB 4b66ef68-338b-4d2c-8323-3e413426204f\r\na=rtcp-mux\r\na=rtcp-rsize\r\na=rtpmap:96 VP8/90000\r\na=rtcp-fb:96 goog-remb\r\na=rtcp-fb:96 transport-cc\r\na=rtcp-fb:96 ccm fir\r\na=rtcp-fb:96 nack\r\na=rtcp-fb:96 nack pli\r\na=rtpmap:97 rtx/90000\r\na=fmtp:97 apt=96\r\na=rtpmap:98 VP9/90000\r\na=rtcp-fb:98 goog-remb\r\na=rtcp-fb:98 transport-cc\r\na=rtcp-fb:98 ccm fir\r\na=rtcp-fb:98 nack\r\na=rtcp-fb:98 nack pli\r\na=fmtp:98 profile-id=0\r\na=rtpmap:99 rtx/90000\r\na=fmtp:99 apt=98\r\na=rtpmap:100 VP9/90000\r\na=rtcp-fb:100 goog-remb\r\na=rtcp-fb:100 transport-cc\r\na=rtcp-fb:100 ccm fir\r\na=rtcp-fb:100 nack\r\na=rtcp-fb:100 nack pli\r\na=fmtp:100 profile-id=2\r\na=rtpmap:101 rtx/90000\r\na=fmtp:101 apt=100\r\na=rtpmap:102 H264/90000\r\na=rtcp-fb:102 goog-remb\r\na=rtcp-fb:102 transport-cc\r\na=rtcp-fb:102 ccm fir\r\na=rtcp-fb:102 nack\r\na=rtcp-fb:102 nack pli\r\na=fmtp:102 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42001f\r\na=rtpmap:122 rtx/90000\r\na=fmtp:122 apt=102\r\na=rtpmap:127 H264/90000\r\na=rtcp-fb:127 goog-remb\r\na=rtcp-fb:127 transport-cc\r\na=rtcp-fb:127 ccm fir\r\na=rtcp-fb:127 nack\r\na=rtcp-fb:127 nack pli\r\na=fmtp:127 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42001f\r\na=rtpmap:121 rtx/90000\r\na=fmtp:121 apt=127\r\na=rtpmap:125 H264/90000\r\na=rtcp-fb:125 goog-remb\r\na=rtcp-fb:125 transport-cc\r\na=rtcp-fb:125 ccm fir\r\na=rtcp-fb:125 nack\r\na=rtcp-fb:125 nack pli\r\na=fmtp:125 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f\r\na=rtpmap:107 rtx/90000\r\na=fmtp:107 apt=125\r\na=rtpmap:108 H264/90000\r\na=rtcp-fb:108 goog-remb\r\na=rtcp-fb:108 transport-cc\r\na=rtcp-fb:108 ccm fir\r\na=rtcp-fb:108 nack\r\na=rtcp-fb:108 nack pli\r\na=fmtp:108 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42e01f\r\na=rtpmap:109 rtx/90000\r\na=fmtp:109 apt=108\r\na=rtpmap:124 red/90000\r\na=rtpmap:120 rtx/90000\r\na=fmtp:120 apt=124\r\na=rtpmap:123 ulpfec/90000\r\na=ssrc-group:FID 2514817883 3089842812\r\na=ssrc:2514817883 cname:sN4lY/QCwlweDDS8\r\na=ssrc:2514817883 msid:bq1tGSK02H1PuMDFtTllrvRqC9dXWTgLyFCB 4b66ef68-338b-4d2c-8323-3e413426204f\r\na=ssrc:2514817883 mslabel:bq1tGSK02H1PuMDFtTllrvRqC9dXWTgLyFCB\r\na=ssrc:2514817883 label:4b66ef68-338b-4d2c-8323-3e413426204f\r\na=ssrc:3089842812 cname:sN4lY/QCwlweDDS8\r\na=ssrc:3089842812 msid:bq1tGSK02H1PuMDFtTllrvRqC9dXWTgLyFCB 4b66ef68-338b-4d2c-8323-3e413426204f\r\na=ssrc:3089842812 mslabel:bq1tGSK02H1PuMDFtTllrvRqC9dXWTgLyFCB\r\na=ssrc:3089842812 label:4b66ef68-338b-4d2c-8323-3e413426204f\r\n","type":"offer"

And answer from webrtcbin as below

"sdp": "v=0\r\no=- 8360833541034081384 0 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\nm=video 9 UDP/TLS/RTP/SAVPF 96\r\nc=IN IP4 0.0.0.0\r\na=ice-ufrag:AqKWFBwNk27K5GortmY8krLAcgqC1JtE\r\na=ice-pwd:y/Ba3mcc+NGno7mrlQz4+0Ov76EEVfmp\r\na=mid:0\r\na=rtcp-mux\r\na=setup:active\r\na=rtpmap:96 VP8/90000\r\na=rtcp-fb:96 nack pli\r\na=rtcp-fb:96 ccm fir\r\na=recvonly\r\na=fingerprint:sha-256 D5:5A:84:8E:BA:92:6F:2E:88:C1:24:20:F6:FA:FE:11:62:96:4B:DE:58:44:1F:09:48:1F:44:3D:7D:E4:5F:D9\r\n", "type": "answer"

But no DTLS client hello triggered by webrtcbin

Please update if something is missing

sampleref commented 4 years ago

Sorry for the long post earlier, but I could figure out that actual cause was with libnice. On machine with GStreamer host actually there were many virtual interfaces, where libnice was exhausting while matching the pairs and logging messages as below

Pruned 1 candidates. Conncheck list has 101 elements left. Maximum connchecks allowed : 100

I could find few suggestions on that (https://gitlab.freedesktop.org/libnice/libnice/issues/95) where libnice can be built with meson option ignored-network-interface-prefix and with that I could make it work. Not sure if its a consistent fix but helped by skipping few non essential interfaces which were exhausting libnice loop