Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Lost connectivity after successful connection #1229

Open
Meonardo opened this issue Jul 9, 2024 · 7 comments
Open

Lost connectivity after successful connection #1229

Meonardo opened this issue Jul 9, 2024 · 7 comments

Comments

@Meonardo
Copy link

Meonardo commented Jul 9, 2024

Thanks for your great work!

I am currently creating a WHEP client on Android to receive audio/video from a SFU server,
I have made to receive and decode the video in the Track::onFrame() callback , but its strange that after around 45s the peerconnection is closed, here is my log:

--------- beginning of main
--------- beginning of system
--------- beginning of kernel
2024-07-09 09:53:28.222 12907-12907 WhepClient  D  rtc::impl::Init::doInit@113: Global initialization
2024-07-09 09:53:28.223 12907-12907 WhepClient  D  rtc::impl::Init::doInit@123: Spawning 4 threads
2024-07-09 09:53:28.227 12907-12958 WhepClient  D  rtc::impl::PollService::runLoop@164: Poll service started
2024-07-09 09:53:28.238 12907-12956 WhepClient  D  rtc::impl::Certificate::Generate@445: Generating certificate (OpenSSL)
2024-07-09 09:53:28.239 12907-12907 WhepClient  D  rtc::impl::IceTransport::IceTransport@58: Initializing ICE transport (libjuice)
2024-07-09 09:53:28.239 12907-12907 WhepClient  W  rtc::impl::IceTransport::IceTransport@94: ICE-TCP is not supported with libjuice
2024-07-09 09:53:28.240 12907-12907 WhepClient  D  rtc::impl::PeerConnection::processLocalDescription@1003: Adding media to local description, mid="0", removed=false
2024-07-09 09:53:28.240 12907-12907 WhepClient  D  rtc::impl::PeerConnection::processLocalDescription@1003: Adding media to local description, mid="1", removed=false
2024-07-09 09:53:28.241 12907-12907 WhepClient  I  rtc::impl::PeerConnection::changeSignalingState@1293: Changed signaling state to have-local-offer
2024-07-09 09:53:28.241 12907-12907 WhepClient  I  rtc::impl::PeerConnection::changeGatheringState@1280: Changed gathering state to in-progress
2024-07-09 09:53:28.241 12907-12907 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Changing state to gathering
2024-07-09 09:53:28.245 12907-12907 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Changing state to connecting
2024-07-09 09:53:28.246 12907-12907 WhepClient  I  rtc::impl::PeerConnection::changeIceState@1262: Changed ICE state to checking
2024-07-09 09:53:28.246 12907-12907 WhepClient  I  rtc::impl::PeerConnection::changeState@1244: Changed state to connecting
2024-07-09 09:53:28.246 12907-12907 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Candidate gathering done
2024-07-09 09:53:28.246 12907-12907 WhepClient  I  rtc::impl::PeerConnection::changeGatheringState@1280: Changed gathering state to complete
2024-07-09 09:53:28.246 12907-12907 WhepClient  I  Call CreateOffer
2024-07-09 09:53:28.247 12907-12907 WhepClient  I  Offer SDP: 

v=0
o=rtc 4264342826 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0 1
a=group:LS 0 1
a=msid-semantic:WMS *
a=ice-options:ice2,trickle
a=fingerprint:sha-256 CA:CF:44:1D:81:F8:12:A9:15:3B:4C:B2:14:D1:91:B8:CF:1F:1F:A5:AE:9B:92:09:AD:17:C9:94:23:28:2B:57
m=audio 37540 UDP/TLS/RTP/SAVPF 100
c=IN IP4 172.16.30.66
a=mid:0
a=recvonly
a=rtcp-mux
a=rtpmap:100 opus/48000/2
a=fmtp:100 minptime=10;maxaveragebitrate=96000;stereo=1;sprop-stereo=1;useinbandfec=1
a=setup:actpass
a=ice-ufrag:Q8Gm
a=ice-pwd:T0U+y1GL6RcXRwhwRZHKcO
a=candidate:1 1 UDP 2122317823 172.16.30.66 37540 typ host
a=end-of-candidates
m=video 37540 UDP/TLS/RTP/SAVPF 96
c=IN IP4 172.16.30.66
a=mid:1
a=recvonly
a=rtcp-mux
a=rtpmap:96 H264/90000
a=rtcp-fb:96 nack
a=rtcp-fb:96 nack pli
a=rtcp-fb:96 goog-remb
a=fmtp:96 profile-level-id=42e01f;packetization-mode=1;level-asymmetry-allowed=1
a=setup:actpass
a=ice-ufrag:Q8Gm
a=ice-pwd:T0U+y1GL6RcXRwhwRZHKcO

2024-07-09 09:53:28.252 12907-12954 WhepClient  I  Ice state is now: Checking
2024-07-09 09:53:28.252 12907-12955 WhepClient  I  PeerConnection state is now: Connecting
2024-07-09 09:53:28.643 12907-12907 WhepClient  I  Call SetRemoteDescription: 

v=0
o=rtc 4264342826 0 IN IP4 192.168.99.101
s=-
t=0 0
a=group:BUNDLE 0 1
a=msid-semantic: WMS *
a=ice-lite
m=audio 8000 UDP/TLS/RTP/SAVPF 100
c=IN IP4 192.168.99.101
a=rtcp:8000 IN IP4 192.168.99.101
a=ice-ufrag:rBEAAh9AIyg=_9
a=ice-pwd:1ngGM6rjgDLwLfcj0fkPJcC6
a=fingerprint:sha-256 5D:43:0F:2C:BD:82:BB:C5:B4:77:42:D3:8C:2B:D5:1A:32:59:39:1D:78:7A:BB:88:E2:EF:2A:60:37:AD:6E:A3
a=setup:passive
a=mid:0
a=ice-lite
a=sendonly
a=rtcp-mux
a=rtpmap:100 opus/48000/2
a=fmtp:100 maxaveragebitrate=96000;minptime=10;sprop-stereo=1;stereo=1;useinbandfec=1
a=msid:zlmediakit-mslabel zlmediakit-label-0
a=ssrc:2 cname:zlmediakit-rtp
a=ssrc:2 msid:zlmediakit-mslabel zlmediakit-label-0
a=ssrc:2 mslabel:zlmediakit-mslabel
a=ssrc:2 label:zlmediakit-label-0
a=candidate:udpcandidate 1 udp 110 192.168.99.101 8000 typ host
a=candidate:tcpcandidate 1 tcp 105 192.168.99.101 9000 typ host tcptype passive
m=video 8000 UDP/TLS/RTP/SAVPF 96
c=IN IP4 192.168.99.101
a=rtcp:8000 IN IP4

2024-07-09 09:53:28.644 12907-12907 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Connectivity timer started
2024-07-09 09:53:28.644 12907-12907 WhepClient  I  rtc::impl::PeerConnection::changeSignalingState@1293: Changed signaling state to stable
2024-07-09 09:53:28.645 12907-12907 WhepClient  W  rtc::impl::IceTransport::LogCallback@390: juice: Ignoring candidate with transport TCP
2024-07-09 09:53:28.646 12907-12961 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Changing state to connected
2024-07-09 09:53:28.646 12907-12961 WhepClient  I  rtc::impl::PeerConnection::changeIceState@1262: Changed ICE state to connected
2024-07-09 09:53:28.646 12907-12961 WhepClient  I  rtc::impl::PeerConnection::initDtlsTransport@278: This connection requires media support
2024-07-09 09:53:28.647 12907-12961 WhepClient  D  rtc::impl::DtlsTransport::DtlsTransport@733: Initializing DTLS transport (OpenSSL)
2024-07-09 09:53:28.650 12907-12954 WhepClient  I  Ice state is now: Connected
2024-07-09 09:53:28.654 12907-12961 WhepClient  D  rtc::impl::DtlsSrtpTransport::DtlsSrtpTransport@69: Initializing DTLS-SRTP transport
2024-07-09 09:53:28.654 12907-12961 WhepClient  D  rtc::impl::DtlsTransport::start@836: Starting DTLS transport
2024-07-09 09:53:28.664 12907-12961 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Changing state to completed
2024-07-09 09:53:28.664 12907-12961 WhepClient  I  rtc::impl::PeerConnection::changeIceState@1262: Changed ICE state to completed
2024-07-09 09:53:28.664 12907-12956 WhepClient  I  Ice state is now: Completed
2024-07-09 09:53:29.261 12907-12907 WhepClient  I  Call add video sink
2024-07-09 09:53:29.663 12907-12955 WhepClient  I  rtc::impl::DtlsTransport::doRecv@959: DTLS handshake finished
2024-07-09 09:53:29.663 12907-12955 WhepClient  I  rtc::impl::DtlsSrtpTransport::postHandshake@303: Deriving SRTP keying material (OpenSSL)
2024-07-09 09:53:29.663 12907-12955 WhepClient  D  rtc::impl::DtlsSrtpTransport::postHandshake@309: SRTP profile is: SRTP_AEAD_AES_256_GCM
2024-07-09 09:53:29.664 12907-12955 WhepClient  I  rtc::impl::PeerConnection::changeState@1244: Changed state to connected
2024-07-09 09:53:29.665 12907-12955 WhepClient  I  PeerConnection state is now: Connected
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
2024-07-09 09:54:27.189 12907-12961 WhepClient  I  rtc::impl::IceTransport::LogCallback@390: juice: Changing state to failed
2024-07-09 09:54:27.189 12907-12961 WhepClient  I  rtc::impl::PeerConnection::changeIceState@1262: Changed ICE state to failed
2024-07-09 09:54:27.189 12907-12961 WhepClient  I  rtc::impl::PeerConnection::changeState@1244: Changed state to failed
2024-07-09 09:54:27.189 12907-12954 WhepClient  I  Ice state is now: Failed
2024-07-09 09:54:27.189 12907-12954 WhepClient  I  PeerConnection state is now: Failed
2024-07-09 09:54:27.189 12907-12954 WhepClient  I  rtc::impl::PeerConnection::changeIceState@1262: Changed ICE state to closed
2024-07-09 09:54:27.190 12907-12954 WhepClient  I  Ice state is now: Closed
2024-07-09 09:54:27.190 12907-12954 WhepClient  I  rtc::impl::PeerConnection::changeState@1244: Changed state to closed
2024-07-09 09:54:27.190 12907-12954 WhepClient  I  PeerConnection state is now: Closed
2024-07-09 09:54:27.190 12907-12954 WhepClient  D  rtc::impl::DtlsTransport::stop@859: Stopping DTLS transport
2024-07-09 09:54:27.190 12907-12956 WhepClient  I  rtc::impl::DtlsTransport::doRecv@991: DTLS closed
2024-07-09 09:54:27.190 12907-12956 WhepClient  D  rtc::impl::DtlsTransport::stop@859: Stopping DTLS transport
2024-07-09 09:54:27.191 12907-12956 WhepClient  D  rtc::impl::DtlsTransport::stop@859: Stopping DTLS transport
2024-07-09 09:54:27.191 12907-12956 WhepClient  D  rtc::impl::DtlsTransport::~DtlsTransport@830: Destroying DTLS transport
2024-07-09 09:54:27.191 12907-12956 WhepClient  D  rtc::impl::IceTransport::~IceTransport@183: Destroying ICE transport

  • I have tried to switch back to libwebrtc, no issue occured;
  • I also tried to connect a different SFU server with libdatachannel, works great.

could you give me some advice? thanks.

@paullouisageneau
Copy link
Owner

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
Copy link
Author

Meonardo commented Jul 9, 2024

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
Copy link
Owner

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

@Meonardo
Copy link
Author

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
Copy link
Owner

paullouisageneau commented Jul 16, 2024

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
Copy link
Author

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
Copy link
Contributor

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 :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants