Lost connectivity after successful connection

[Meonardo]

Lost connectivity after successful connection

[paullouisageneau]

2024-07-09 09:54:27.188 12907-12961 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: STUN entry 0: Consent expired for candidate pair
2024-07-09 09:54:27.189 12907-12961 WhepClient  W  rtc::impl::IceTransport::LogCallback@390: juice: Lost connectivity

It looks like the SFU stops answering ICE STUN requests after connection, which makes libjuice timeout as it implements ICE Consent freshness (RFC7675). The SFU probably has a broken ICE implementation.

You can build libdatachannel with -DDISABLE_CONSENT_FRESHNESS=1 (only libjuice needs to be rebuild in practice) to mitigate the issue by falling back to legacy keepalives.

[Meonardo]

The issue still exists after I rebuild libdatachannel with:

cmake -B build -DUSE_GNUTLS=0 -DUSE_NICE=0 -DCMAKE_BUILD_TYPE=Release -DOPENSSL_USE_STATIC_LIBS=1 \ 
-DDISABLE_CONSENT_FRESHNESS=1 -DOPENSSL_ROOT_DIR=/home/meonardo/Android/openssl \ 
-DCMAKE_TOOLCHAIN_FILE=/home/meonardo/Android/NDK/android-ndk-r25c/build/cmake/android.toolchain.cmake \ 
-DANDROID_ABI="arm64-v8a" -DANDROID_PLATFORM="android-21" -DCMAKE_INSTALL_PREFIX=$current_dir/build/install

the Lost connectivity is gone, but after a period time, no more video data from Track::onFrame() callback,

2024-07-09 17:58:41.560 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Entering poll on 1 sockets for 0 ms
2024-07-09 17:58:41.560 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Leaving poll
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Received datagram, size=30
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Not a STUN message: first 2 bits are not zeroes
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Received non-STUN datagram from 192.168.99.101:8000
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: STUN selected entry matching incoming address
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Received application datagram
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::RecvCallback@363: Incoming size=30
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::DtlsTransport::incoming@892: Incoming size=30
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Receiving datagram
2024-07-09 17:58:41.564 15472-15550 WhepClient  D  rtc::impl::DtlsSrtpTransport::demuxMessage@215: Demultiplexing DTLS and SRTP/SRTCP with first byte, value=128
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Received datagram, size=40
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Not a STUN message: first 2 bits are not zeroes
2024-07-09 17:58:41.564 15472-15550 WhepClient  D  rtc::impl::DtlsSrtpTransport::recvMedia@153: Demultiplexing SRTCP and SRTP with RTP payload type, value=96
2024-07-09 17:58:41.564 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Received non-STUN datagram from 192.168.99.101:8000
2024-07-09 17:58:41.564 15472-15550 WhepClient  D  rtc::IsRtcp@39: Demultiplexing RTCP and RTP with payload type, value=96
2024-07-09 17:58:41.565 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: STUN selected entry matching incoming address
2024-07-09 17:58:41.565 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Received application datagram
2024-07-09 17:58:41.565 15472-15557 WhepClient  D  rtc::impl::IceTransport::RecvCallback@363: Incoming size=40
2024-07-09 17:58:41.565 15472-15557 WhepClient  D  rtc::impl::DtlsTransport::incoming@892: Incoming size=40
2024-07-09 17:58:41.566 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: No more datagrams to receive
2024-07-09 17:58:41.566 15472-15553 WhepClient  D  rtc::impl::DtlsSrtpTransport::recvMedia@153: Demultiplexing SRTCP and SRTP with RTP payload type, value=96
2024-07-09 17:58:41.566 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Bookkeeping...
2024-07-09 17:58:41.566 15472-15553 WhepClient  D  rtc::IsRtcp@39: Demultiplexing RTCP and RTP with payload type, value=96
2024-07-09 17:58:41.566 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Entering poll on 1 sockets for 0 ms
2024-07-09 17:58:41.566 15472-15553 WhepClient  D  rtc::impl::DtlsSrtpTransport::recvMedia@177: Incoming SRTP packet, size=91
2024-07-09 17:58:41.566 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Leaving poll
2024-07-09 17:58:41.566 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Bookkeeping...
2024-07-09 17:58:41.567 15472-15553 WhepClient  D  rtc::impl::DtlsSrtpTransport::recvMedia@191: Unprotected SRTP packet, size=75
2024-07-09 17:58:41.567 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Entering poll on 1 sockets for 0 ms
2024-07-09 17:58:41.567 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Leaving poll
2024-07-09 17:58:41.567 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Bookkeeping...
2024-07-09 17:58:41.567 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Entering poll on 1 sockets for 0 ms
2024-07-09 17:58:41.567 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Leaving poll
2024-07-09 17:58:41.567 15472-15557 WhepClient  D  rtc::impl::IceTransport::LogCallback@390: juice: Bookkeeping...

...

2024-07-09 17:58:44.146 15472-15557 WhepClient D  rtc::impl::IceTransport::LogCallback@390: juice: Leaving poll
2024-07-09 17:58:44.146 15472-15557 WhepClient D  rtc::impl::IceTransport::LogCallback@390: juice: Bookkeeping...

the 192.168.99.101 is where my SFU server installed.

[paullouisageneau]

The server might actually be going away. Have you set an RtcpReceivingSession before the depacketizer?

[Meonardo]

Sorry for later response.

Have you set an RtcpReceivingSession before the depacketizer?

Yes, I already did, actually I was following the whep-source example in OBS .

[paullouisageneau]

Hmm, the OBS code looks incorrect, it should be:

	auto audio_depacketizer = std::make_shared<rtc::OpusRtpDepacketizer>();
	audio_depacketizer->addToChain(std::make_shared<rtc::RtcpReceivingSession>());
	audio_track->setMediaHandler(audio_depacketizer);

Otherwise, the RTCP session is not attached anywhere and simply ignored.

@Sean-Der Are you aware of this? I remember discussing the media handler chain with you at some point.

[Meonardo]

Thanks for you time, sadly, the issue still persisted, I have updated my code to:

  rtc::Description::Video videoMedia("1", rtc::Description::Direction::RecvOnly);
  videoMedia.addH264Codec(96);
  video_track_ = pc_->addTrack(videoMedia);

  auto video_depacketizer = std::make_shared<rtc::H264RtpDepacketizer>();
  auto video_session = std::make_shared<rtc::RtcpReceivingSession>();
  video_depacketizer->addToChain(video_session);
  video_track_->setMediaHandler(video_depacketizer);
  video_track_->onFrame([&](const rtc::binary &msg, rtc::FrameInfo frame_info) {
	OnVideoPacket(msg, frame_info);
  });

  pc_->setLocalDescription();

Here is a public test SFU server ZLMediaKit that I am testing for my WHEP client.

[Sean-Der]

This sounds similar to pion/webrtc#2767

Thank you @paullouisageneau I will fix that and send you the PR. I bet that will improve QoS a bit :)