webrtcsink: extend critical section during connection setup (!1316) · Merge requests · GStreamer / gst-plugins-rs

Dan Burkert requested to merge danburkert/gst-plugins-rs:webrtcbin-race into main Sep 01, 2023

This addresses the intermittent connection failure described in 1. I traced the issue to a race condition between setting up a new webrtc connection and receiving a callback for new ICE candidates. It seems that during the call to session.connect_input_stream, the session is removed from the state container, and the state lock is dropped. If a new ICE candidate message is received, the handler will subsequently fail to find the associated session and things fail.

The fix is crude: the state lock critical section is extended to include connection setup. In theory this may introduce a possibility of deadlock, but in testing it's been solid.

Example of relevant logs for a successful connection setup (with some of my own log lines added tagged with DCB):

0:00:00.686453000 95050    0x139a27860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2049:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}::{{closure}}: rtprtxsend doesn't have a `stuffing-kbps` property, stuffing disabled
0:00:00.686733000 95050    0x139a27860 DEBUG             webrtcsink net/webrtc/src/webrtcsink/imp.rs:2765:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::handle_sdp_answer::{{closure}}: received reply Ok(None)
0:00:00.686743000 95050    0x139a27860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2557:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; REMOVE session_id: unique
0:00:00.686750000 95050    0x139a27860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2580:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; DROPPING state lock
0:00:00.686753000 95050    0x139a27860 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:980:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<livekitwebrtcsink0> Connecting input stream video_0 for consumer unique and media 0
0:00:00.686755000 95050    0x139a27860 DEBUG             webrtcsink net/webrtc/src/webrtcsink/imp.rs:1001:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<livekitwebrtcsink0> Picking codec from local offer
0:00:00.689691000 95050    0x139a27860 DEBUG             webrtcsink net/webrtc/src/webrtcsink/imp.rs:3551:<gstrswebrtc::webrtcsink::imp::BaseWebRTCSink as glib::subclass::object::ObjectImpl>::signals::SIGNALS::{{closure}}::{{closure}}:<livekitwebrtcsink0> applying default configuration on encoder Element { inner: TypedObjectRef { inner: 0x139aa0170, type: GstVP8Enc } }
0:00:00.689751000 95050    0x139762a90 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:00.689808000 95050    0x139762a90 WARN    webrtctransportsendbin transportsendbin.c:459:gst_transport_send_bin_element_query:<transportsendbin0> did not really configure latency of 0:00:00.000000000
0:00:00.689983000 95050    0x139a27860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2597:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; REACQUIRING state lock
0:00:00.689992000 95050    0x139a27860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2648:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; INSERT session_id: unique
0:00:00.690950000 95050    0x139a27860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2135:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Ice connection state in session unique (peer unique) changed: Checking
0:00:00.690961000 95050    0x139a27860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2101:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Connection state in session unique (peer unique) changed: Connecting
0:00:00.717958000 95050    0x139762a90 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:00.718017000 95050    0x139762a90 WARN    webrtctransportsendbin transportsendbin.c:459:gst_transport_send_bin_element_query:<transportsendbin0> did not really configure latency of 0:00:00.000000000
0:00:00.722124000 95050    0x139762a90 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:00.722168000 95050    0x139762a90 WARN    webrtctransportsendbin transportsendbin.c:459:gst_transport_send_bin_element_query:<transportsendbin0> did not really configure latency of 0:00:00.000000000
0:00:00.849323000 95050    0x139a27860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2135:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Ice connection state in session unique (peer unique) changed: Connected
0:00:00.849559000 95050    0x139762a90 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:00.868478000 95050    0x139a27860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2101:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Connection state in session unique (peer unique) changed: Connected
0:00:00.917212000 95050    0x139762a90 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:00.917385000 95050    0x139762a90 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:02.741931000 95050    0x139a27860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2172:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Ice gathering state in session unique (peer unique) changed: Complete
0:00:02.791983000 95050    0x139a27860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2135:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Ice connection state in session unique (peer unique) changed: Completed
0:00:04.582464000 95050    0x139762a90 DEBUG   webrtc-livekit-signaller net/webrtc/src/livekit_signaller/imp.rs:156:gstrswebrtc::livekit_signaller::imp::Signaller::on_signal_event::{{closure}}:<GstLiveKitWebRTCSinkSignaller@0x1399af220> Connection quality: ConnectionQualityUpdate { updates: [ConnectionQualityInfo { participant_sid: "PA_Yf4vJUBtrh9h", quality: Excellent, score: 4.5 }] }
0:00:09.583011000 95050    0x139762a90 DEBUG   webrtc-livekit-signaller net/webrtc/src/livekit_signaller/imp.rs:156:gstrswebrtc::livekit_signaller::imp::Signaller::on_signal_event::{{closure}}:<GstLiveKitWebRTCSinkSignaller@0x1399af220> Connection quality: ConnectionQualityUpdate { updates: [ConnectionQualityInfo { participant_sid: "PA_Yf4vJUBtrh9h", quality: Good, score: 3.2669215 }] }

Corresponding logs for a failed setup case:

0:00:01.009986000 94819    0x145207860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2049:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}::{{closure}}: rtprtxsend doesn't have a `stuffing-kbps` property, stuffing disabled
0:00:01.010291000 94819    0x144f40ca0 DEBUG   webrtc-livekit-signaller net/webrtc/src/livekit_signaller/imp.rs:140:gstrswebrtc::livekit_signaller::imp::Signaller::on_signal_event::{{closure}}:<GstLiveKitWebRTCSinkSignaller@0x14518e1a0> Received ice_candidate TrickleRequest { candidate_init: "{\"candidate\":\"candidate:1872232515 1 udp 2130706431 147.182.231.136 58960 typ host\",\"sdpMid\":\"\",\"sdpMLineIndex\":0,\"usernameFragment\":null}", target: Publisher }
0:00:01.010296000 94819    0x145207860 DEBUG             webrtcsink net/webrtc/src/webrtcsink/imp.rs:2765:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::handle_sdp_answer::{{closure}}: received reply Ok(None)
0:00:01.010305000 94819    0x145207860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2557:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; REMOVE session_id: unique
0:00:01.010312000 94819    0x145207860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2580:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; DROPPING state lock
0:00:01.010316000 94819    0x145207860 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:980:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<livekitwebrtcsink0> Connecting input stream video_0 for consumer unique and media 0
0:00:01.010318000 94819    0x145207860 DEBUG             webrtcsink net/webrtc/src/webrtcsink/imp.rs:1001:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<livekitwebrtcsink0> Picking codec from local offer
0:00:01.010322000 94819    0x144f40ca0 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2682:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::handle_ice: No consumer with ID unique
0:00:01.010388000 94819    0x144f40ca0 DEBUG   webrtc-livekit-signaller net/webrtc/src/livekit_signaller/imp.rs:140:gstrswebrtc::livekit_signaller::imp::Signaller::on_signal_event::{{closure}}:<GstLiveKitWebRTCSinkSignaller@0x14518e1a0> Received ice_candidate TrickleRequest { candidate_init: "{\"candidate\":\"candidate:3530256803 1 tcp 1671430143 147.182.231.136 7881 typ host tcptype passive\",\"sdpMid\":\"\",\"sdpMLineIndex\":0,\"usernameFragment\":null}", target: Publisher }
0:00:01.010393000 94819    0x144f40ca0 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2682:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::handle_ice: No consumer with ID unique
0:00:01.012778000 94819    0x145207860 DEBUG             webrtcsink net/webrtc/src/webrtcsink/imp.rs:3551:<gstrswebrtc::webrtcsink::imp::BaseWebRTCSink as glib::subclass::object::ObjectImpl>::signals::SIGNALS::{{closure}}::{{closure}}:<livekitwebrtcsink0> applying default configuration on encoder Element { inner: TypedObjectRef { inner: 0x1452842d0, type: GstVP8Enc } }
0:00:01.012845000 94819    0x144f40ca0 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:01.012903000 94819    0x144f40ca0 WARN    webrtctransportsendbin transportsendbin.c:459:gst_transport_send_bin_element_query:<transportsendbin0> did not really configure latency of 0:00:00.000000000
0:00:01.013100000 94819    0x145207860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2597:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; REACQUIRING state lock
0:00:01.013108000 94819    0x145207860 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2648:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::on_remote_description_set: DCB: on_remote_description_set; INSERT session_id: unique
0:00:01.015029000 94819    0x144f40ca0 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:01.015060000 94819    0x144f40ca0 WARN    webrtctransportsendbin transportsendbin.c:459:gst_transport_send_bin_element_query:<transportsendbin0> did not really configure latency of 0:00:00.000000000
0:00:01.018762000 94819    0x144f40ca0 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2280:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique> Recalculating latency
0:00:01.018793000 94819    0x144f40ca0 WARN    webrtctransportsendbin transportsendbin.c:459:gst_transport_send_bin_element_query:<transportsendbin0> did not really configure latency of 0:00:00.000000000
0:00:03.060803000 94819    0x145207860 LOG               webrtcsink net/webrtc/src/webrtcsink/imp.rs:2172:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<livekitwebrtcsink0> Ice gathering state in session unique (peer unique) changed: Complete
0:00:36.080916000 94819    0x144f40ca0 DEBUG   webrtc-livekit-signaller net/webrtc/src/livekit_signaller/imp.rs:104:gstrswebrtc::livekit_signaller::imp::Signaller::signal_task::{{closure}}:<GstLiveKitWebRTCSinkSignaller@0x14518e1a0> Close

Admin message

webrtcsink: extend critical section during connection setup

Merge request reports