search

paullouisageneau / libdatachannel

C/C++ WebRTC network library featuring Data Channels, Media Transport, and WebSockets
https://libdatachannel.org/
Mozilla Public License 2.0
1.81k stars 366 forks source link

Lost connectivity after successful connection #1229

Open Meonardo opened 4 months ago

Meonardo commented 4 months ago

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

could you give me some advice? thanks.

paullouisageneau commented 4 months ago 
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 commented 4 months ago

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 commented 4 months ago

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

Meonardo commented 4 months ago

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 commented 4 months ago

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 commented 4 months ago

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 commented 4 months ago

This sounds similar to https://github.com/pion/webrtc/issues/2767

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