Auto reconnect in whipeclientsink

I use the following to stream video and audio over an unstable mobile connection:

gst-launch-1.0 whipclientsink signaller::whip-endpoint="http://xxxx:xxx@xxx:8889/live/fly/whip" name=ws video-caps="video/x-vp8"  \
  v4l2src device=${VIDEO} ! tee name=v \
  v. ! queue leaky=1 ! autovideosink sync=false \
  v. ! queue ! ws.  \
  pulsesrc device=${MIC_AUDIO} ! queue ! gareus-org-oss-lv2-nodelay-mega delay=11000 ! audiomixer name=a \
  pulsesrc device=${HDMI_AUDIO} ! queue ! a. \
  a. ! ws.

The server is mediamtx.

This commands stream to the server and display a local monitor window with video.

I have two issues:

  • The quality is adapted to the connection, BUT, if the connection drops, it does not restart. I have to kill and relaunch the command.
  • Sometimes, the sound cracks for about 30 seconds

Hmm, I’m not sure what the expectation from the spec is on ICE connection failure, but it seems like it might make sense for the application to explicitly manage restarting the pipeline, rather than having the stream automatically restart?

For sound cracking, I might be interesting to stick in a tee after the audiomixer and dump the audio locally, make sure the send side hasn’t seen any issues. For example, if your system is under load, it could be that either the source or your filter is not able to provide data quickly enough for a short period, and that could manifest as dropped buffers?

I will try to tee but it seems to be related to the bandwidth management algorithm.

You can see it here https://www.kuon.ch/twitch/vods/2024-06-10-15-36-18-vol/ at 1:21:35 exactly. When I move the camera, I think the congestion algorithm kicks in, and we can see some frames are dropped and the sound start cracking, and after a few seconds it gets back to normal.

About the reconnection, I would expect gstreamer to handle it, as the congestion control algorithm is the source of the current bandwidth available, but if it is out of the scope of gstreamer, I can write a small script that monitor network interface datarate, and restart when it hit zero for a few seconds.

I notice similar glitches around 1:18:14 (entirely by accident!) that seem unrelated to the video, assuming the chat overlay is part of the video, but I haven’t looked too closely.

@taruntej was working on some ICE consent freshness feedback that might tie into restarting ICE, maybe that helps here (I’ll let him weigh in on that).

I have verified the behavior on my system with whipserversrc and there it is able to reconnect properly once the network is restored.

@kuon do you have the logs of the whipclient/webrtcsink somewhere so I can take a look?

It is hard to reproduce the real conditions as I had those issues while doing a mobile stream.

I am trying to reproduce this in my office, I will let you know and share the logs.

I made a flight today, and I captured the log this time.

I start the pipeline with this:

export GST_DEBUG=webrtcsink:6
VIDEO=/dev/v4l/by-id/usb-Video_Grabber_HDMI_to_U3_capture_20000130041415-video-index0
HDMI_AUDIO=alsa_input.usb-Video_Grabber_HDMI_to_U3_capture_20000130041415-02.analog-stereo
MIC_AUDIO=alsa_input.pci-0000_05_00.6.3.analog-stereo

LOG=log/$(date +%F_%T)-stream.log

pactl set-source-volume alsa_input.usb-Video_Grabber_HDMI_to_U3_capture_20000130041415-02.analog-stereo 3% &>> $LOG
pactl set-source-volume alsa_input.pci-0000_05_00.6.analog-stereo 10% &>> $LOG



mkdir -p log

gst-launch-1.0 whipclientsink signaller::whip-endpoint="http://kuon:xxx@xxx:8889/live/fly/whip" name=ws video-caps="video/x-vp8"  \
  v4l2src device=${VIDEO} ! tee name=v \
  v. ! queue leaky=1 ! autovideosink sync=false \
  v. ! queue ! ws.  \
  pulsesrc device=${MIC_AUDIO} ! queue ! gareus-org-oss-lv2-nodelay-mega delay=11000 ! audiomixer name=a \
  pulsesrc device=${HDMI_AUDIO} ! queue ! a. \
  a. ! ws. \
  &>> $LOG

At present, I have a bandwidth indicator on my notebook, and when it hit zero, I restart the script (that’s why you see interrupt at the end).

I have about 20 of those logs, as I restarted everytime, but they look very similar.

Setting pipeline to PAUSED ...
0:00:00.099951217 e[35m 4990e[00m 0x60f14fc40310 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1787:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::prepare:<ws>e[00m preparing
Pipeline is live and does not need PREROLL ...
Got context from element 'autovideosink0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayWayland\)\ gldisplaywayland0";
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
0:00:00.103057136 e[35m 4990e[00m 0x75b618000df0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3486:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::sink_event:<ws:video_0>e[00m Received caps event Caps { seqnum: Seqnum(166), running-time-offset: 0, structure: Some(GstEventCaps { caps: (GstCaps) video/x-raw, format=(string)YUY2, width=(int)1920, height=(int)1080, framerate=(fraction)60/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive, colorimetry=(string)2:4:5:1 }), caps: Caps(video/x-raw(memory:SystemMemory) { format: (gchararray) "YUY2", width: (gint) 1920, height: (gint) 1080, framerate: (GstFraction) 60/1, pixel-aspect-ratio: (GstFraction) 1/1, interlace-mode: (gchararray) "progressive", colorimetry: (gchararray) "2:4:5:1" }) }
Redistribute latency...
Redistribute latency...
New clock: GstPulseSrcClock
0:00:00.121191990 e[35m 4990e[00m 0x75b618001050 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3486:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::sink_event:<ws:audio_0>e[00m Received caps event Caps { seqnum: Seqnum(202), running-time-offset: 0, structure: Some(GstEventCaps { caps: (GstCaps) audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)1, layout=(string)interleaved }), caps: Caps(audio/x-raw(memory:SystemMemory) { format: (gchararray) "F32LE", rate: (gint) 44100, channels: (gint) 1, layout: (gchararray) "interleaved" }) }
Redistribute latency...
0:00:00.122367177 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3194:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:<ws>e[00m Running discovery pipeline for input caps audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)1, layout=(string)interleaved and output caps ANY with codec Codec { name: "OPUS", caps: Caps(audio/x-opus(memory:SystemMemory)), stream_type: StreamType(AUDIO), payload_type: Some(97), decoding_info: Some(DecodingInfo { has_decoder: true }), encoding_info: Some(EncodingInfo { encoder: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5b1790, type: GstElementFactory } }, payloader: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5c5c10, type: GstElementFactory } }, output_filter: None }) }
0:00:00.122428632 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3200:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:<ws>e[00m Running discovery pipeline
0:00:00.124158457 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3967:<gstrswebrtc::webrtcsink::imp::BaseWebRTCSink as glib::subclass::object::ObjectImpl>::signals::SIGNALS::{{closure}}::{{closure}}:<ws>e[00m applying default configuration on encoder Element { inner: TypedObjectRef { inner: 0x75b5d00161a0, type: GstOpusEnc } }
0:00:00.124200766 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1505:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::configure_congestion_control:<rtpopuspay0>e[00m Mapping TWCC extension to ID 1
Redistribute latency...
0:00:00.159123745 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3194:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:<ws>e[00m Running discovery pipeline for input caps video/x-raw, format=(string)YUY2, width=(int)1920, height=(int)1080, framerate=(fraction)60/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive, colorimetry=(string)2:4:5:1 and output caps ANY with codec Codec { name: "VP8", caps: Caps(video/x-vp8(memory:SystemMemory)), stream_type: StreamType(VIDEO), payload_type: Some(96), decoding_info: Some(DecodingInfo { has_decoder: true }), encoding_info: Some(EncodingInfo { encoder: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5860d0, type: GstElementFactory } }, payloader: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5d9d50, type: GstElementFactory } }, output_filter: None }) }
0:00:00.159182615 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3200:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:<ws>e[00m Running discovery pipeline
Redistribute latency...
0:00:00.188982784 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3967:<gstrswebrtc::webrtcsink::imp::BaseWebRTCSink as glib::subclass::object::ObjectImpl>::signals::SIGNALS::{{closure}}::{{closure}}:<ws>e[00m applying default configuration on encoder Element { inner: TypedObjectRef { inner: 0x75b5d004b5e0, type: GstVP8Enc } }
0:00:00.189070368 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1505:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::configure_congestion_control:<rtpvp8pay0>e[00m Mapping TWCC extension to ID 1
0:00:00.189634764 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3315:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:e[00m Discovery pipeline got caps Caps(application/x-rtp(memory:SystemMemory) { media: (gchararray) "audio", clock-rate: (gint) 48000, encoding-name: (gchararray) "OPUS", sprop-stereo: (gchararray) "0", encoding-params: (gchararray) "2", sprop-maxcapturerate: (gchararray) "48000", payload: (gint) 97, ssrc: (guint) 3276587311, timestamp-offset: (guint) 2918877556, seqnum-offset: (guint) 19796, extmap-1: (gchararray) "http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01" })
0:00:00.189695878 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3331:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:<ws>e[00m Codec discovery pipeline for caps audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)1, layout=(string)interleaved with codec Codec { name: "OPUS", caps: Caps(audio/x-opus(memory:SystemMemory)), stream_type: StreamType(AUDIO), payload_type: Some(97), decoding_info: Some(DecodingInfo { has_decoder: true }), encoding_info: Some(EncodingInfo { encoder: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5b1790, type: GstElementFactory } }, payloader: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5c5c10, type: GstElementFactory } }, output_filter: None }) } succeeded: application/x-rtp, media=(string)audio, clock-rate=(int)48000, encoding-name=(string)OPUS, sprop-stereo=(string)0, encoding-params=(string)2, sprop-maxcapturerate=(string)48000, payload=(int)97, extmap-1=(string)http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01;
0:00:00.213372455 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3315:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:e[00m Discovery pipeline got caps Caps(application/x-rtp(memory:SystemMemory) { media: (gchararray) "video", clock-rate: (gint) 90000, encoding-name: (gchararray) "VP8", payload: (gint) 96, ssrc: (guint) 1985692418, timestamp-offset: (guint) 1057003140, seqnum-offset: (guint) 20109, a-framerate: (gchararray) "60", extmap-1: (gchararray) "http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01" })
0:00:00.213491157 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3331:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::run_discovery_pipeline::{{closure}}:<ws>e[00m Codec discovery pipeline for caps video/x-raw, format=(string)YUY2, width=(int)1920, height=(int)1080, framerate=(fraction)60/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive, colorimetry=(string)2:4:5:1 with codec Codec { name: "VP8", caps: Caps(video/x-vp8(memory:SystemMemory)), stream_type: StreamType(VIDEO), payload_type: Some(96), decoding_info: Some(DecodingInfo { has_decoder: true }), encoding_info: Some(EncodingInfo { encoder: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5860d0, type: GstElementFactory } }, payloader: ElementFactory { inner: TypedObjectRef { inner: 0x60f14f5d9d50, type: GstElementFactory } }, output_filter: None }) } succeeded: application/x-rtp, media=(string)video, clock-rate=(int)90000, encoding-name=(string)VP8, payload=(int)96, extmap-1=(string)http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01;
0:00:00.215720867 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2359:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session:<ws>e[00m Adding session: unique for peer: unique
0:00:00.222601194 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1731:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::request_webrtcbin_pad::{{closure}}:<ws>e[00m Requesting WebRTC pad with caps application/x-rtp, media=(string)video, clock-rate=(int)90000, encoding-name=(string)VP8, payload=(int)96, extmap-1=(string)http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01, ssrc=(uint)848199581
0:00:00.222724164 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1731:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::request_webrtcbin_pad::{{closure}}:<ws>e[00m Requesting WebRTC pad with caps application/x-rtp, media=(string)audio, clock-rate=(int)48000, encoding-name=(string)OPUS, sprop-stereo=(string)0, encoding-params=(string)2, sprop-maxcapturerate=(string)48000, payload=(int)97, extmap-1=(string)http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01, ssrc=(uint)908022468
0:00:00.222901786 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2235:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::negotiate:<ws>e[00m Negotiating for session unique
0:00:00.222929538 e[35m 4990e[00m 0x75b5d00046a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2259:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::negotiate:e[00m Creating offer for session unique
0:00:00.282464353 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:00.282671441 e[35m 4990e[00m 0x75b5d00055a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2262:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::negotiate::{{closure}}:e[00m Created offer for session unique
0:00:00.283874841 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2563:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Ice gathering state in session unique (peer unique) changed: Gathering
0:00:00.484166014 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2563:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Ice gathering state in session unique (peer unique) changed: Complete
0:00:03.271126189 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mWARN   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2440:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}::{{closure}}:e[00m rtprtxsend doesn't have a `stuffing-kbps` property, stuffing disabled
0:00:03.271686356 e[35m 4990e[00m 0x75b5d00055a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3153:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::handle_sdp_answer::{{closure}}:e[00m received reply Ok(None)
0:00:03.271720109 e[35m 4990e[00m 0x75b5d00055a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1209:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<ws>e[00m Connecting input stream audio_0 for consumer unique and media 1
0:00:03.271734486 e[35m 4990e[00m 0x75b5d00055a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1230:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<ws>e[00m Picking codec from local offer
0:00:03.272173628 e[35m 4990e[00m 0x75b5d00055a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3967:<gstrswebrtc::webrtcsink::imp::BaseWebRTCSink as glib::subclass::object::ObjectImpl>::signals::SIGNALS::{{closure}}::{{closure}}:<ws>e[00m applying default configuration on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac0faff0, type: GstOpusEnc } }
0:00:03.272239511 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.272537949 e[35m 4990e[00m 0x75b5d00055a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1209:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<ws>e[00m Connecting input stream video_0 for consumer unique and media 0
0:00:03.272564378 e[35m 4990e[00m 0x75b5d00055a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1230:gstrswebrtc::webrtcsink::imp::Session::connect_input_stream:<ws>e[00m Picking codec from local offer
0:00:03.279582633 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.280198324 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.283780163 e[35m 4990e[00m 0x75b5d00055a0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:3967:<gstrswebrtc::webrtcsink::imp::BaseWebRTCSink as glib::subclass::object::ObjectImpl>::signals::SIGNALS::{{closure}}::{{closure}}:<ws>e[00m applying default configuration on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:03.283880350 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.284236827 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2526:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Ice connection state in session unique (peer unique) changed: Checking
0:00:03.284269248 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2492:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Connection state in session unique (peer unique) changed: Connecting
0:00:03.298304034 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.306707209 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.446933304 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2526:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Ice connection state in session unique (peer unique) changed: Connected
0:00:03.447006511 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2526:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Ice connection state in session unique (peer unique) changed: Completed
0:00:03.447394927 e[35m 4990e[00m 0x75b5d00046a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2671:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<session-pipeline-unique>e[00m Recalculating latency
0:00:03.521189900 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2492:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Connection state in session unique (peer unique) changed: Connected
0:00:04.175450446 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 1991196 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)720, width=(int)1280 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:04.373340689 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 2043966 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:22.580245994 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 1941708 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)720, width=(int)1280 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:23.278317570 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 2018415 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:24.081418951 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 1991624 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)720, width=(int)1280 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:24.808436389 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 2014364 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:26.695131839 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 1950521 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)720, width=(int)1280 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:27.714712536 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 379035 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)360, width=(int)640, framerate=(fraction)30/1 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:36.777693673 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 500666 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)360, width=(int)640 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:00:45.972615601 e[35m 4990e[00m 0x75b618002350 e[33;01mLOG    e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1032:gstrswebrtc::webrtcsink::imp::VideoEncoder::set_bitrate:<ws>e[00m session unique: setting bitrate 1014053 and caps video/x-raw(ANY), pixel-aspect-ratio=(fraction)1/1, height=(int)720, width=(int)1280 on encoder Element { inner: TypedObjectRef { inner: 0x75b5ac10b490, type: GstVP8Enc } }
0:01:18.770030496 e[35m 4990e[00m 0x75b5d00055a0 e[33;01mWARN   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:2516:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws>e[00m Ice connection state in session unique (peer unique) failed
0:01:18.770164987 e[35m 4990e[00m 0x75b5d00055a0 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1061:gstrswebrtc::webrtcsink::imp::State::finalize_session:e[00m Ending session unique
0:01:33.781019570 e[35m 4990e[00m 0x75b57c0015e0 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1093:gstrswebrtc::webrtcsink::imp::State::finalize_session::{{closure}}:e[00m Session unique ended
handling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:02:15.510831677
Setting pipeline to NULL ...
0:02:15.612505496 e[35m 4990e[00m 0x60f14fc40310 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1802:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m unpreparing
0:02:15.612624509 e[35m 4990e[00m 0x60f14fc40310 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1826:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m Waiting for codec discoveries to finish
0:02:15.612650738 e[35m 4990e[00m 0x60f14fc40310 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1833:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m No codec discovery is running anymore
0:02:15.612680283 e[35m 4990e[00m 0x60f14fc40310 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1844:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m Ending sessions
0:02:15.612700020 e[35m 4990e[00m 0x60f14fc40310 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1848:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m All sessions have started finalizing
0:02:15.612724746 e[35m 4990e[00m 0x60f14fc40310 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1851:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m Stopping signaller
0:02:15.612751496 e[35m 4990e[00m 0x60f14fc40310 e[36mINFO   e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1853:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m Stopped signaller
0:02:15.612770161 e[35m 4990e[00m 0x60f14fc40310 e[37mDEBUG  e[00m e[00m          webrtcsink net/webrtc/src/webrtcsink/imp.rs:1864:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::unprepare:<ws>e[00m All sessions are done finalizing
Freeing pipeline ...

For context, I use this pipeline to display a video monitor on my notebook while streaming, and for audio, I mix two audio cards, one with a small delay.

The ICE Connection seems to failed as per the logs. The connection goes to failed state if the ice candidate pairs are not compatible.

The ICE candidate has checked all candidates pairs against one another and has failed to find compatible matches for all components of the connection. It is, however, possible that the ICE agent did find compatible connections for some components.

Is it possible that the ICE candidates are changing when your connection drops and restores? We can check what the ice candidates are in the SDP from the whipclientsink logs by adding whip*:6 to the GST_DEBUG

Ok, I am able to reproduce it 100% in my lab with some aluminum foil on the antenna, so it is much easier to debug.

I wanted to gather some logs, but with whip*:6 as GST_DEBUG I get no debug log.

Also, the ICE session ends when the connection is re-established.

I am sorry, it should be webrtc-whip*:6 or webrtc-whip-signaller:6 to be precise

Ok, the below log is on the following timeline:

0s: starting
15s: putting foil on antenna
25s: removing foil
40s: interrupt

I looked on the server side, and I think the session is closed because the server does not receive any data, then when the connection is restored, the web rtc signaler tries to close the already closed session:


Jul 20 21:38:05 puma mediamtx[732142]: 2024/07/20 21:38:05 DEB [WebRTC] [session 14670c2a] peer connection state: connected
Jul 20 21:38:05 puma mediamtx[732142]: 2024/07/20 21:38:05 INF [WebRTC] [session 14670c2a] peer connection established, local candidate: host/udp/185.131.204.14/8189, remote candidate: prflx/udp/xxxx/63297
Jul 20 21:38:05 puma mediamtx[732142]: 2024/07/20 21:38:05 INF [WebRTC] [session 14670c2a] is publishing to path 'live/fly', 2 tracks (Opus, VP8)
Jul 20 21:38:21 puma mediamtx[732142]: 2024/07/20 21:38:21 DEB [WebRTC] [session 14670c2a] peer connection state: disconnected
Jul 20 21:38:21 puma mediamtx[732142]: 2024/07/20 21:38:21 DEB [WebRTC] [session 14670c2a] peer connection state: closed
Jul 20 21:38:21 puma mediamtx[732142]: 2024/07/20 21:38:21 INF [WebRTC] [session 14670c2a] closed: peer connection closed
Jul 20 21:38:21 puma mediamtx[732142]: 2024/07/20 21:38:21 DEB [path live/fly] destroyed: not in use
Jul 20 21:38:41 puma mediamtx[732142]: 2024/07/20 21:38:41 DEB [WebRTC] [conn xxxx:32791] [c->s] DELETE /live/fly/whip/6769610d-b41c-49f2-88cd-825c5773d3ef HTTP/1.1
Jul 20 21:38:41 puma mediamtx[732142]: Host: puma.e42.ch:8889
Jul 20 21:38:41 puma mediamtx[732142]: Accept: */*
Jul 20 21:38:41 puma mediamtx[732142]: Accept-Encoding: gzip
Jul 20 21:38:41 puma mediamtx[732142]: Authorization: Basic xxxx
Jul 20 21:38:41 puma mediamtx[732142]: 
Jul 20 21:38:41 puma mediamtx[732142]: 2024/07/20 21:38:41 DEB [WebRTC] [conn xxxx:32791] [s->c] HTTP/1.1 500 Internal Server Error
Jul 20 21:38:41 puma mediamtx[732142]: Access-Control-Allow-Credentials: true
Jul 20 21:38:41 puma mediamtx[732142]: Access-Control-Allow-Origin: *
Jul 20 21:38:41 puma mediamtx[732142]: Content-Type: application/json; charset=utf-8
Jul 20 21:38:41 puma mediamtx[732142]: Server: mediamtx
Jul 20 21:38:41 puma mediamtx[732142]: (body of 29 bytes)

Yes that is what I can confirm from the below snippet of webrtc-whip-signaller logs as well

0:00:32.079910596 30932 0x7b6f28036170 DEBUG    webrtcnicetransport nicetransport.c:293:_on_component_state_changed:<webrtcnicetransport0> 1 1 failed
0:00:32.079968094 30932 0x7b6f28036170 LOG     webrtctransportsendbin transportsendbin.c:274:maybe_start_enc:<transportsendbin0> Can't start DTLS yet because ICE is not connected.
0:00:32.080008159 30932 0x7b6f28036170 LOG     webrtctransportreceivebin transportreceivebin.c:132:transport_receive_bin_set_receive_state:<transportreceivebin0> Can't unblock nicesrc yet because ICE is not connected, it is 4
0:00:32.080022566 30932 0x630da09f27b0 INFO               webrtcbin gstwebrtcbin.c:1660:_update_ice_connection_state_task:<webrtcbin-unique> ICE connection state change from completed(3) to failed(4)
0:00:32.080103707 30932 0x630da09f27b0 WARN              webrtcsink net/webrtc/src/webrtcsink/imp.rs:2516:gstrswebrtc::webrtcsink::imp::BaseWebRTCSink::start_session::{{closure}}:<ws> Ice connection state in session unique (peer unique) failed
0:00:32.080152018 30932 0x630da09f27b0 INFO              webrtcsink net/webrtc/src/webrtcsink/imp.rs:1061:gstrswebrtc::webrtcsink::imp::State::finalize_session: Ending session unique
0:00:32.080240313 30932 0x630da09f27b0 DEBUG   webrtc-whip-signaller net/webrtc/src/whip_signaller/imp.rs:412:gstrswebrtc::whip_signaller::imp::WhipClient::terminate_session:<GstWhipClientSignaller@0x630da05948f0> DELETE request on http://kuon:xxx@xxx:8889/live/fly/whip/f8f9144a-0032-4328-9ed3-977632b9b967
0:00:32.080347614 30932 0x7b6ed0001680 DEBUG              webrtcbin gstwebrtcbin.c:8002:gst_webrtc_bin_change_state: changing state: PLAYING => PAUSED
0:00:32.080410742 30932 0x7b6ed0001680 DEBUG   webrtctransportsendbin transportsendbin.c:165:transport_send_bin_change_state:<transportsendbin0> changing state: PLAYING => PAUSED
0:00:32.080570621 30932 0x7b6ed0001680 DEBUG   webrtctransportreceivebin transportreceivebin.c:237:transport_receive_bin_change_state: changing state: PLAYING => PAUSED
0:00:32.080892763 30932 0x7b6ed0001680 DEBUG              webrtcbin gstwebrtcbin.c:8002:gst_webrtc_bin_change_state: changing state: PAUSED => READY
0:00:32.081069514 30932 0x7b6ed0001680 DEBUG   webrtctransportsendbin transportsendbin.c:165:transport_send_bin_change_state:<transportsendbin0> changing state: PAUSED => READY
0:00:32.083565973 30932 0x7b6ed0001680 DEBUG   webrtctransportreceivebin transportreceivebin.c:237:transport_receive_bin_change_state: changing state: PAUSED => READY
0:00:32.084536900 30932 0x7b6ed0001680 DEBUG              webrtcbin gstwebrtcbin.c:8002:gst_webrtc_bin_change_state: changing state: READY => NULL
0:00:32.084571735 30932 0x7b6ed0001680 DEBUG   webrtctransportsendbin transportsendbin.c:165:transport_send_bin_change_state:<transportsendbin0> changing state: READY => NULL
0:00:32.084655542 30932 0x7b6ed0001680 DEBUG   webrtctransportreceivebin transportreceivebin.c:237:transport_receive_bin_change_state: changing state: READY => NULL
0:00:32.178969242 30932 0x630da09f27b0 DEBUG   webrtc-whip-signaller net/webrtc/src/whip_signaller/imp.rs:431:gstrswebrtc::whip_signaller::imp::WhipClient::terminate_session:<GstWhipClientSignaller@0x630da05948f0> Response to DELETE : 500 Internal Server Error
0:00:32.179726198 30932 0x630da09f27b0 DEBUG              webrtcbin gstwebrtcbin.c:1184:_execute_op:<webrtcbin-unique> Peerconnection is closed, aborting execution

The DELETE request has failed because the server had already cleaned up the session due to webrtc connection failure.

So I think there is no way for webrtcwebrtcsink or webrtcbin to reattempt to connect a ‘Failed’ session, the application has to restart with a new session

I think it would make sense for gstreamer to try to reconnect itself. An application would require a lot of information that gstreamer has (dropped packets, connection quality, session state…) and would have to handle it all to reconnect at the correct time.

I mean, the whole point of the congestion control algorithm is to allow running on a bad connection, and I think it would serve a lot of users to handle this case directly within gstreamer.

This been said, I understand if it cannot happen (for reason like ICE protocol compliance or any other possible reason). And I guess I’ll just write a wrapper that simply parse the log and restart the whole pipeline if the connection fails.

Instead of the log parsing there is a much cleaner way to get notified about the connection state when it changes.

Based on the version you are using, you can connect to the consumer-added or webrtcbin-ready signal on the whipclientsink and access the webrtcbin. Further you can connect to ice-connection-state signal on the webrcbin and get a callback whenever there is change in the connection state, you can then do the necessary steps in the callback.

In C you can do g_signal_connect (webrtcbin, "notify::ice-connection-state", G_CALLBACK (on_ice_connection_state_notify), NULL);

Here is how we do the same in webrtcsink - net/webrtc/src/webrtcsink/imp.rs · main · GStreamer / gst-plugins-rs · GitLab

I created a working app in C that can run my pipeline, but I cannot find how to connect the signal.

I use gst_parse_launch to create my pipeline object, but from here, I don’t know how to get the webrtcbin to attach the signal to.

I’m able to get the whipclientsink with gst_bin_get_by_name using the ws name I set in my pipeline, but I don’t know how to get the webrtcbin from there.

To get the webrtcbin from webrtcsink you can connect to the consumer-added signal: webrtcsink

Ok, I’m able to get the notification now (I’ll share my code for reference when I am done).

Now, I have one last issue (last for now). It’s the timeout. It takes about 30 seconds for the ice-connection-state to switch to failed. Is there a way to alter this timeout?

No, the timeout is a fixed timeout specified in RFC7675.