Kurento / bugtracker

[ARCHIVED] Contents migrated to monorepo: https://github.com/Kurento/kurento
46 stars 10 forks source link

Kurento failing to stream to the client / listener occasionally / non deterministically #235

Open virtualfunction opened 6 years ago

virtualfunction commented 6 years ago

I've using the official docker image for Kurento (the 6.6.2 tag, because 6.7.0 segfaults with ICE negotiation for me atm). Obviously the gstreamer libraries are the same as the supplied docker container (attached details at bottom of the report)

I'm trying to stream using (broadcast) RTP -> (listener) WebRTC, it's OPUS one way audio only. I have about 20 streams broadcast into separate "rooms", which do broadcast more-less at the same time, but it only fails one to one or two of the rooms oddly (so I wonder if it's race / locking / blocking issue inside Kurento). Whichever room(s) fail, fail on the client side regardless whatever the browser, and the audio is getting to Kurento which leads me to believe it's an internal issue.

This happens both on server and locally (i.e. it's not a ICE / TURN / STUN / Firewall issue). I know this for a fact because I see Kurento responds to the MediaFlowOutStateChange event when the broadcast is started, so it's clearly getting the incoming audio via RTP. I also know this because I can capture the incoming RTP on the server to a PCAP, copy it and play it back fine, so clearly Kurento is getting the audio and I can rule out any broadcasting issues. Likewise I'd very much doubt it's networking related, there's virtually no packet loss or anything like that as I have a 1Gb/s Internet connection between broadcast PC and server, and the ping a consistent 7-8ms.

The broadcast PC connects to the server via a VPN (i.e. Openvpn 2.4 over UDP) because I've blocked UDP access from outside. I'm using the following command to broadcast, obviously I'm using JACK here, because it does a good job of allowing us to customise our audio pipeline, but audiotestsrc obviously can suffice here.

# Run on broadcast PC
gst-launch-1.0 -v jackaudiosrc client-name=webrtc_test ! queue max-size-time=40000000 ! audio/x-raw,channels=1 ! audioconvert ! audioresample ! opusenc bitrate=96000 packet-loss-percentage=8 ! rtpopuspay pt=98 ssrc=642382330 ! queue max-size-time=40000000 ! udpsink port=34690 host=192.168.242.1
# Capture on server
sudo tcpdump -T rtp -i any -w /tmp/rtp_opus_audio.pcap port 34690
# Play back locally on dev PC
AUDIO_CAPS='application/x-rtp,media=(string)audio,clock-rate=(int)48000,encoding-name=(string)X-GST-OPUS-DRAFT-SPITTKA-00'
gst-launch-1.0 filesrc location=~/rtp_opus_audio.pcap ! queue ! pcapparse caps=$AUDIO_CAPS ! "application/x-rtp, payload=98" ! rtpopusdepay ! opusdec ! autoaudiosink

The offer SDP I've giving to the server is this:

v=0
t=0 0
m=audio 4100 RTP/AVP 98
c=IN IP4 127.0.0.1
a=recvonly
a=rtpmap:98 opus/48000/2
a=fmtp:98 stereo=0; sprop-stereo=0; useinbandfec=1

The server's answer is this:

v=0
o=- 3729340777 3729340777 IN IP4 172.24.0.1
s=Kurento Media Server
c=IN IP4 172.24.0.1
t=0 0
m=audio 34690 RTP/AVP 98
a=rtpmap:98 opus/48000/2
a=sendonly
a=fmtp:98 stereo=0; sprop-stereo=0; useinbandfec=1
a=ssrc:642382330 cname:user321891642@host-7db24f87

The 172.24.0.1 IP is the KMS is shared with 192.168.242.1. The 172.24.0.0/16 network is docker container , and 192.168.242.1 is the VPN/tun0 on 192.168.242.0/24, hence the IP discrepancy between the gsteamer broadcast and SDP. It's not an issue like I say because I can media events and tcpdump picks up traffic.

The client is based on the one2many listener (I have several broadcasters so the signalling is slightly different to allow for multiple rooms / channels). Like I say it typically fails on maybe one or two rooms, and it's not deterministic. On the room that fails for broadcast it consistently fails on Chrome (64 x64 on Ubuntu 17.10) and Firefox (using 58.0.2 in Ubuntu 17.10). It doesn't seem to be a browser issue, given it happens on whatever the affected room fails consistently ion both browsers

Here's a log of the console messages from Chrome 64:

[0.021] Sending message: viewer {"auth_code":"authenticated","channel_name":"audio_test","sdp_offer":"v=0\r\no=- 4161326762189520216 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio\r\na=msid-semantic: WMS\r\nm=audio 33785 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126\r\nc=IN IP4 172.18.0.1\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=candidate:1051995033 1 udp 2122260223 172.18.0.1 33785 typ host generation 0 network-id 1 network-cost 50\r\na=candidate:4062063367 1 udp 2122194687 172.19.0.1 51898 typ host generation 0 network-id 2 network-cost 50\r\na=candidate:3594748867 1 udp 2122129151 192.168.1.72 39616 typ host generation 0 network-id 3\r\na=ice-ufrag:nadW\r\na=ice-pwd:pGEumOZPePrW/7g7NnvGPxfs\r\na=ice-options:trickle\r\na=fingerprint:sha-256 42:DB:72:E1:F5:65:BB:A6:D4:44:28:78:2C:00:FE:49:52:B4:0F:EE:2F:FE:6F:B4:04:77:D6:41:7E:39:E3:EE\r\na=setup:actpass\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:14 urn:ietf:params:rtp-hdrext:encrypt urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=recvonly\r\na=rtcp-mux\r\na=rtpmap:111 opus/48000/2\r\na=rtcp-fb:111 transport-cc\r\na=fmtp:111 minptime=10;useinbandfec=1\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:9 G722/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:110 telephone-event/48000\r\na=rtpmap:112 telephone-event/32000\r\na=rtpmap:113 telephone-event/16000\r\na=rtpmap:126 telephone-event/8000\r\n"}
[0.022] Local candidate{"candidate":"candidate:1051995033 1 udp 2122260223 172.18.0.1 33785 typ host generation 0 ufrag nadW network-id 1 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.022] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:1051995033 1 udp 2122260223 172.18.0.1 33785 typ host generation 0 ufrag nadW network-id 1 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.024] Local candidate{"candidate":"candidate:4062063367 1 udp 2122194687 172.19.0.1 51898 typ host generation 0 ufrag nadW network-id 2 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.024] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:4062063367 1 udp 2122194687 172.19.0.1 51898 typ host generation 0 ufrag nadW network-id 2 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.024] Local candidate{"candidate":"candidate:3594748867 1 udp 2122129151 192.168.1.72 39616 typ host generation 0 ufrag nadW network-id 3","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.024] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:3594748867 1 udp 2122129151 192.168.1.72 39616 typ host generation 0 ufrag nadW network-id 3","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.074] Local candidate{"candidate":"candidate:3717574005 1 udp 1686052607 51.7.39.158 33785 typ srflx raddr 172.18.0.1 rport 33785 generation 0 ufrag nadW network-id 1 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.074] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:3717574005 1 udp 1686052607 51.7.39.158 33785 typ srflx raddr 172.18.0.1 rport 33785 generation 0 ufrag nadW network-id 1 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.074] Local candidate{"candidate":"candidate:542374423 1 udp 1685921535 51.7.39.158 39616 typ srflx raddr 192.168.1.72 rport 39616 generation 0 ufrag nadW network-id 3","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.075] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:542374423 1 udp 1685921535 51.7.39.158 39616 typ srflx raddr 192.168.1.72 rport 39616 generation 0 ufrag nadW network-id 3","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.076] Local candidate{"candidate":"candidate:289385963 1 udp 1685987071 51.7.39.158 51898 typ srflx raddr 172.19.0.1 rport 51898 generation 0 ufrag nadW network-id 2 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.076] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:289385963 1 udp 1685987071 51.7.39.158 51898 typ srflx raddr 172.19.0.1 rport 51898 generation 0 ufrag nadW network-id 2 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.120] Local candidate{"candidate":"candidate:1882707817 1 tcp 1518280447 172.18.0.1 9 typ host tcptype active generation 0 ufrag nadW network-id 1 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.121] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:1882707817 1 tcp 1518280447 172.18.0.1 9 typ host tcptype active generation 0 ufrag nadW network-id 1 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.121] Local candidate{"candidate":"candidate:3164461047 1 tcp 1518214911 172.19.0.1 9 typ host tcptype active generation 0 ufrag nadW network-id 2 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.121] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:3164461047 1 tcp 1518214911 172.19.0.1 9 typ host tcptype active generation 0 ufrag nadW network-id 2 network-cost 50","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.122] Local candidate{"candidate":"candidate:2562752307 1 tcp 1518149375 192.168.1.72 9 typ host tcptype active generation 0 ufrag nadW network-id 3","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}
[0.123] Sending message: on_ice_candidate {"candidate":{"candidate":"candidate:2562752307 1 tcp 1518149375 192.168.1.72 9 typ host tcptype active generation 0 ufrag nadW network-id 3","sdpMid":"audio","sdpMLineIndex":0,"usernameFragment":"nadW"}}
[0.135] Answered OK
[0.137] Listening
[0.137] {"response":"accepted","sdp_answer":"v=0\r\no=- 3729391543 3729391543 IN IP4 0.0.0.0\r\ns=Kurento Media Server\r\nc=IN IP4 0.0.0.0\r\nt=0 0\r\na=msid-semantic: WMS\r\na=group:BUNDLE audio\r\nm=audio 1 UDP/TLS/RTP/SAVPF 111 0\r\na=mid:audio\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=rtpmap:111 opus/48000/2\r\na=rtpmap:0 PCMU/8000\r\na=setup:active\r\na=sendonly\r\na=rtcp-mux\r\na=fmtp:111 minptime=10;useinbandfec=1\r\na=ssrc:1554496700 cname:user3679917224@host-4c07366b\r\na=ice-ufrag:WJT/\r\na=ice-pwd:soiXY02zFdi6oVZprcJNRb\r\na=fingerprint:sha-256 B1:75:D8:48:F7:D7:CB:CF:D1:6A:40:94:C4:C2:9E:C5:F0:59:C2:D3:15:33:16:68:8C:1A:92:6F:5A:89:84:32\r\n","uid":"1"}

Here's my full KMS details should they be needed

0:00:00.012118638   569       0xf994f0 INFO    KurentoModuleManager ModuleManager.cpp:173:loadModules: Found module: /usr/lib/x86_64-linux-gnu/kurento/modules/libkmsfiltersmodule.so
0:00:00.013350197   569       0xf994f0 DEBUG   KurentoModuleManager ModuleManager.cpp:89:loadModule: Module loaded from /usr/lib/x86_64-linux-gnu/kurento/modules/libkmsfiltersmodule.so
0:00:00.013372288   569       0xf994f0 INFO    KurentoModuleManager ModuleManager.cpp:135:loadModule: Loaded filters version 6.6.2 generated at Jul 25 2017 13:36:15
0:00:00.013390472   569       0xf994f0 INFO    KurentoModuleManager ModuleManager.cpp:173:loadModules: Found module: /usr/lib/x86_64-linux-gnu/kurento/modules/libkmscoremodule.so
0:00:00.013926568   569       0xf994f0 DEBUG   KurentoModuleManager ModuleManager.cpp:89:loadModule: Module loaded from /usr/lib/x86_64-linux-gnu/kurento/modules/libkmscoremodule.so
0:00:00.013947650   569       0xf994f0 INFO    KurentoModuleManager ModuleManager.cpp:135:loadModule: Loaded core version 6.6.3 generated at Aug 11 2017 19:36:36
0:00:00.013967996   569       0xf994f0 INFO    KurentoModuleManager ModuleManager.cpp:173:loadModules: Found module: /usr/lib/x86_64-linux-gnu/kurento/modules/libkmselementsmodule.so
0:00:00.022884278   569       0xf994f0 DEBUG   KurentoModuleManager ModuleManager.cpp:89:loadModule: Module loaded from /usr/lib/x86_64-linux-gnu/kurento/modules/libkmselementsmodule.so
0:00:00.022923729   569       0xf994f0 INFO    KurentoModuleManager ModuleManager.cpp:135:loadModule: Loaded elements version 6.6.3 generated at Aug 11 2017 20:18:10
Version: 6.6.2
Found modules:
    Module: 'core' version '6.6.3'
    Module: 'elements' version '6.6.3'
    Module: 'filters' version '6.6.2'
ii  gstreamer1.5-libav:amd64             1.8.2.1~20160909143244.96.g493eee4.trusty  amd64        libav plugin for GStreamer
ii  gstreamer1.5-nice:amd64              0.1.13.1~20160930090742.81.geebfdab.trusty amd64        ICE library (GStreamer plugin)
ii  gstreamer1.5-plugins-bad:amd64       1.8.1.1~20160909144557.99.gf836e53.trusty  amd64        GStreamer plugins from the "bad" set
ii  gstreamer1.5-plugins-base:amd64      1.8.1.1~20160909142623.55.g7b19cfd.trusty  amd64        GStreamer plugins from the "base" set
ii  gstreamer1.5-plugins-good:amd64      1.8.1.1~20160909143047.112.g9ee4248.trusty amd64        GStreamer plugins from the "good" set
ii  gstreamer1.5-plugins-ugly:amd64      1.8.1.1~20160909192513.89.g2685b0f.trusty  amd64        GStreamer plugins from the "ugly" set
ii  gstreamer1.5-pulseaudio:amd64        1.8.1.1~20160909143047.112.g9ee4248.trusty amd64        GStreamer plugin for PulseAudio
ii  gstreamer1.5-x:amd64                 1.8.1.1~20160909142623.55.g7b19cfd.trusty  amd64        GStreamer plugins for X11 and Pango
ii  kms-core-6.0                         6.6.3.trusty.20170811193010.2704d13        amd64        Kurento core module
ii  kms-elements-6.0                     6.6.3.trusty.20170811201004.9e3fff4        amd64        Kurento elements module
ii  kms-filters-6.0                      6.6.2.trusty.20170725133434.7b4c9ea        amd64        Kurento filters module
ii  kms-jsonrpc-1.0                      1.1.3.trusty.20170725112926.ee575c6        amd64        Kurento jsonrpc library
ii  kmsjsoncpp                           1.6.3.trusty.20170725122830.d78deb7        amd64        Kurento jsoncpp library
ii  kurento-media-server-6.0             6.6.2.trusty.20170725135150.8e7ceee        amd64        Kurento Media Server
ii  libgstreamer-plugins-bad1.5-0:amd64  1.8.1.1~20160909144557.99.gf836e53.trusty  amd64        GStreamer development files for libraries from the "bad" set
ii  libgstreamer-plugins-base1.5-0:amd64 1.8.1.1~20160909142623.55.g7b19cfd.trusty  amd64        GStreamer libraries from the "base" set
ii  libgstreamer1.5-0:amd64              1.8.1.1~20160909144007.170.g0d6031b.trusty amd64        Core GStreamer libraries and elements
ii  libnice10:amd64                      0.1.13.1~20160930090742.81.geebfdab.trusty amd64        ICE library (shared library)

When I get more time to look I'll double check to make sure to see if useinbandfec isn't causing issues, but I very much doubt it as I recall it happening when I disabled this in the SDP and the packet-loss-percentage gstreamer broadcast options. I'll also see when I have time if spacing out the gstreamer broadcast with sleep commands between each stream helps prevent this. I seem to recall it happening regardless.

buzeandrei commented 6 years ago

Any update on this?