Skip to content
This repository has been archived by the owner on Jul 12, 2023. It is now read-only.

Kurento media server keeps connections open after the end of the video session. #253

Closed
IonHubber opened this issue Jun 1, 2018 · 8 comments
Assignees

Comments

@IonHubber
Copy link

KMS Version:
Kurento Media Server version: 6.7.1
Found modules:
'core' version 6.7.1
'elements' version 6.7.1
'filters' version 6.7.1

Other libraries versions:
ii gstreamer1.5-libav:amd64 1.8.2.120160909143244.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.120160909144557.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.120160909143047.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.120160909143047.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.7.1.trusty.20180322151212.47e0370 amd64 Kurento Core module
ii kms-elements 6.7.1.trusty.20180322161851.5aaf4a0 amd64 Kurento Elements module
ii kms-filters 6.7.1.trusty.20180322170020.7f2d045 amd64 Kurento Filters module
ii kms-jsonrpc 6.7.1.trusty20180322150101.1.637bf2a amd64 Kurento JSON-RPC library
ii kmsjsoncpp 1.6.3.trusty.20170725122830.d78deb7 amd64 Kurento jsoncpp library
ii kurento-media-server 6.7.1.trusty.20180322174246.dd49a2c 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.120160909142623.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.120160930090742.81.geebfdab.trusty amd64 ICE library (shared library)
ii openh264-gst-plugins-bad-1.5:amd64 1.8.1.1
20160909144557.99.gf836e53.trusty amd64 GStreamer plugins from openh264

Client libraries

  • Language: Java
  • Version: 1.8

Browsers tested
Add OK or FAIL, along with the version, after browsers where you
have tested this issue:

  • Chrome: OK
  • Firefox: OK
  • Native: OK

System description:
KMS located on the same computer where is the kurento-tutorial-java started.

What steps will reproduce the problem?

  1. Start video recording.
  2. Stop video recording.
  3. Close browser.

What is the expected result?
Websocket connection from browser is closed, stream connection on KMS is destroyed.

What happens instead?
Websocket connection from browser is closed, stream connection on KMS is live.

Does it happen with one of the tutorials?
Yes. 'kurento-tutorial-java' 6.7.1

Please provide any additional information below.
Each new video record/play connection init unix stream connection. After the end user session (closing browser, for example) stream connection not destroyed. At the end we can see 5k+ active connections and more.

netstat -anpl | grep kurento-media | grep unix | wc -l

unix 3 [ ] STREAM CONNECTED 369547 26730/kurento-media
unix 3 [ ] STREAM CONNECTED 369269 26730/kurento-media
unix 3 [ ] STREAM CONNECTED 364356 26730/kurento-media
unix 3 [ ] STREAM CONNECTED 373253 26730/kurento-media
unix 3 [ ] STREAM CONNECTED 370551 26730/kurento-media
unix 3 [ ] STREAM CONNECTED 373006 26730/kurento-media
unix 3 [ ] STREAM CONNECTED 364093 26730/kurento-media
...

@jlongman
Copy link

jlongman commented Jun 6, 2018

Did you destroy the pipelines?

@IonHubber
Copy link
Author

You are right. I do not destroy pipeline. I added follow lines:
`// HelloWorldRecHandler.java
...
case "stop":
if (user != null) {
user.stop();
// new line
user.release();
}
break;
...

//UserSession.java
...
public void release() {
this.mediaPipeline.release();
this.webRtcEndpoint = null;
//new line
this.recorderEndpoint = null;
this.mediaPipeline = null;
if (this.stopTimestamp == null) {
this.stopTimestamp = new Date();
}
}
...
`
Some of connections destroyed now. But after end of record/play activity I still have unidentified connections:

netstat -anp | grep kur
tcp6 0 0 :::8888 :::* LISTEN 32513/kurento-media
tcp6 0 0 127.0.0.1:8888 127.0.0.1:59022 ESTABLISHED 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 197579 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 197593 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 198573 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 198574 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 197578 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 199700 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 197594 32513/kurento-media
unix 3 [ ] STREAM CONNECTED 199699 32513/kurento-media

There is correlation by number in lsof with following:

KmsLoop 32513 32612 kurento 12u unix 0xffff880078c28000 0t0 197578 socket
KmsLoop 32513 32612 kurento 13u unix 0xffff880078c2bc00 0t0 197579 socket
KmsLoop 32513 32612 kurento 17u unix 0xffff880078c29e00 0t0 197593 socket
KmsLoop 32513 32612 kurento 18u unix 0xffff880078c2a580 0t0 197594 socket
KmsLoop 32513 32612 kurento 19u unix 0xffff880029828000 0t0 198573 socket
KmsLoop 32513 32612 kurento 20u unix 0xffff880029829e00 0t0 198574 socket
KmsLoop 32513 32612 kurento 21u unix 0xffff8800298283c0 0t0 199699 socket
KmsLoop 32513 32612 kurento 22u unix 0xffff88002982a940 0t0 199700 socket
GstSystem 32513 32617 kurento 12u unix 0xffff880078c28000 0t0 197578 socket
GstSystem 32513 32617 kurento 13u unix 0xffff880078c2bc00 0t0 197579 socket
GstSystem 32513 32617 kurento 17u unix 0xffff880078c29e00 0t0 197593 socket
GstSystem 32513 32617 kurento 18u unix 0xffff880078c2a580 0t0 197594 socket
GstSystem 32513 32617 kurento 19u unix 0xffff880029828000 0t0 198573 socket
GstSystem 32513 32617 kurento 20u unix 0xffff880029829e00 0t0 198574 socket
GstSystem 32513 32617 kurento 21u unix 0xffff8800298283c0 0t0 199699 socket
GstSystem 32513 32617 kurento 22u unix 0xffff88002982a940 0t0 199700 socket

What is 'KmsLoop' and 'GstSystem'? Thanks.

@ifplusor
Copy link

@jlongman Why kurento do not close socket before destroy MediaPipeline but WebrtcEndpoint is release?

@j1elo
Copy link
Member

j1elo commented Apr 21, 2020

Wait until the Kurento garbage collector runs, to see if the sockets are released. By default the garbage collector runs every 240 seconds.

Change the Debug Logging to add this: KurentoMediaSet:5

Now you should be able to see DEBUG messages from the MediaSet class. Then wait for this message:

Running garbage collector

@j1elo j1elo self-assigned this Apr 21, 2020
@ifplusor
Copy link

ifplusor commented Apr 25, 2020

@j1elo I saw "Running garbage collector" in log, but socket not close after that time. And after release MediaPipeline, it also not close.

kurento log:

2020-04-26T05:03:28,132428 14068 0x00007fba0ad12700   debug KurentoMediaSet           MediaSet.cpp:123 doGarbageCollection()  Running garbage collector
2020-04-26T05:03:28,303508 14068 0x00007fba05507700    info KurentoWebSocketTransport WebSocketTransport.cpp:296 keepAliveSessions()  Keep alive 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:03:41,460789 14068 0x00007fba0750b700    info kmsutils                  kmsutils.c:494 kms_utils_pad_monitor_gaps() <'':sink>  Add probe: Detect stream gaps
2020-04-26T05:03:41,461175 14068 0x00007fba0750b700    info kmsutils                  kmsutils.c:494 kms_utils_pad_monitor_gaps() <'':sink>  Add probe: Detect stream gaps
2020-04-26T05:03:41,461354 14068 0x00007fba0750b700    info kmsutils                  kmsutils.c:494 kms_utils_pad_monitor_gaps() <'':sink_video_default>  Add probe: Detect stream gaps
2020-04-26T05:03:41,869566 14068 0x00007fba0a511700    info rtpsynchronizer           kmsrtpsynchronizer.c:141 kms_rtp_synchronizer_init_stats_file() <KmsRtpSynchronizer@0x7fb978004890>  No path for stats; enable with env variable: 'KMS_RTP_SYNC_STATS_PATH'
2020-04-26T05:03:41,869672 14068 0x00007fba0a511700    info rtpsynchronizer           kmsrtpsynchronizer.c:141 kms_rtp_synchronizer_init_stats_file() <KmsRtpSynchronizer@0x7fb970023420>  No path for stats; enable with env variable: 'KMS_RTP_SYNC_STATS_PATH'
2020-04-26T05:03:41,870246 14068 0x00007fba0a511700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:111 BaseRtpEndpointImpl()  Predefined RTP MTU: 1200
2020-04-26T05:03:41,870325 14068 0x00007fba0a511700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:104 remove_not_supported_codecs_from_array() <kmswebrtcendpoint21>  Removing not supported codec 'PCMA/8000'
2020-04-26T05:03:41,870376 14068 0x00007fba0a511700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:104 remove_not_supported_codecs_from_array() <kmswebrtcendpoint21>  Removing not supported codec 'AMR/8000'
2020-04-26T05:03:41,870459 14068 0x00007fba0a511700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:521 WebRtcEndpointImpl()  No predefined external IP address found in config; you can set one or default to STUN automatic discovery
2020-04-26T05:03:41,870514 14068 0x00007fba0a511700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:527 WebRtcEndpointImpl()  Predefined network interfaces: eno1
2020-04-26T05:03:41,870587 14068 0x00007fba0a511700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:539 WebRtcEndpointImpl()  STUN port not found in config; using default value: 3478
2020-04-26T05:03:41,870641 14068 0x00007fba0a511700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:564 WebRtcEndpointImpl()  Using TURN relay server: <user:password>@172.16.1.10:3478?transport=udp
2020-04-26T05:03:41,870910 14068 0x00007fba0a511700    info kmswebrtcsession          kmswebrtcsession.c:1680 kms_webrtc_session_parse_turn_url() <kmswebrtcsession21>  TURN server info set: <user:password>@172.16.1.10:3478?transport=udp
2020-04-26T05:03:41,875568 14068 0x00007fba06509700    info kmssdpsession             kmssdpsession.c:95 kms_sdp_session_process_offer() <kmswebrtcsession21>  Process SDP Offer:
v=0
o=- 8872385803205144075 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0 1
a=msid-semantic: WMS 4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1
m=audio 9 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 0.0.0.0
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:CNY+
a=ice-pwd:w8CqiyB/IxmYwWRh6Lb6orh8
a=ice-options:trickle
a=fingerprint:sha-256 27:D8:B3:70:34:F3:1A:58:33:71:02:88:60:1E:8C:6C:5A:36:6C:39:CF:91:23:21:33:76:6C:CE:24:46:7F:58
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1 22263ec3-5e97-43c2-959c-a3bde6d28186
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:3405239752 cname:VIch5gFwZWnmeoRt
a=ssrc:3405239752 msid:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1 22263ec3-5e97-43c2-959c-a3bde6d28186
a=ssrc:3405239752 mslabel:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1
a=ssrc:3405239752 label:22263ec3-5e97-43c2-959c-a3bde6d28186
m=video 9 UDP/TLS/RTP/SAVPF 96 97 98 99 100 101 102 122 127 121 125 107 108 109 124 120 123 119 114 115 116
c=IN IP4 0.0.0.0
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:CNY+
a=ice-pwd:w8CqiyB/IxmYwWRh6Lb6orh8
a=ice-options:trickle
a=fingerprint:sha-256 27:D8:B3:70:34:F3:1A:58:33:71:02:88:60:1E:8C:6C:5A:36:6C:39:CF:91:23:21:33:76:6C:CE:24:46:7F:58
a=setup:actpass
a=mid:1
a=extmap:14 urn:ietf:params:rtp-hdrext:toffset
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:13 urn:3gpp:video-orientation
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:12 http://www.webrtc.org/experiments/rtp-hdrext/playout-delay
a=extmap:11 http://www.webrtc.org/experiments/rtp-hdrext/video-content-type
a=extmap:7 http://www.webrtc.org/experiments/rtp-hdrext/video-timing
a=extmap:8 http://tools.ietf.org/html/draft-ietf-avtext-framemarking-07
a=extmap:9 http://www.webrtc.org/experiments/rtp-hdrext/color-space
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1 2dd8cc28-21f7-4fb7-8847-19da24730488
a=rtcp-mux
a=rtcp-rsize
a=rtpmap:96 VP8/90000
a=rtcp-fb:96 goog-remb
a=rtcp-fb:96 transport-cc
a=rtcp-fb:96 ccm fir
a=rtcp-fb:96 nack
a=rtcp-fb:96 nack pli
a=rtpmap:97 rtx/90000
a=fmtp:97 apt=96
a=rtpmap:98 VP9/90000
a=rtcp-fb:98 goog-remb
a=rtcp-fb:98 transport-cc
a=rtcp-fb:98 ccm fir
a=rtcp-fb:98 nack
a=rtcp-fb:98 nack pli
a=fmtp:98 profile-id=0
a=rtpmap:99 rtx/90000
a=fmtp:99 apt=98
a=rtpmap:100 VP9/90000
a=rtcp-fb:100 goog-remb
a=rtcp-fb:100 transport-cc
a=rtcp-fb:100 ccm fir
a=rtcp-fb:100 nack
a=rtcp-fb:100 nack pli
a=fmtp:100 profile-id=2
a=rtpmap:101 rtx/90000
a=fmtp:101 apt=100
a=rtpmap:102 H264/90000
a=rtcp-fb:102 goog-remb
a=rtcp-fb:102 transport-cc
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli
a=fmtp:102 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42001f
a=rtpmap:122 rtx/90000
a=fmtp:122 apt=102
a=rtpmap:127 H264/90000
a=rtcp-fb:127 goog-remb
a=rtcp-fb:127 transport-cc
a=rtcp-fb:127 ccm fir
a=rtcp-fb:127 nack
a=rtcp-fb:127 nack pli
a=fmtp:127 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42001f
a=rtpmap:121 rtx/90000
a=fmtp:121 apt=127
a=rtpmap:125 H264/90000
a=rtcp-fb:125 goog-remb
a=rtcp-fb:125 transport-cc
a=rtcp-fb:125 ccm fir
a=rtcp-fb:125 nack
a=rtcp-fb:125 nack pli
a=fmtp:125 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f
a=rtpmap:107 rtx/90000
a=fmtp:107 apt=125
a=rtpmap:108 H264/90000
a=rtcp-fb:108 goog-remb
a=rtcp-fb:108 transport-cc
a=rtcp-fb:108 ccm fir
a=rtcp-fb:108 nack
a=rtcp-fb:108 nack pli
a=fmtp:108 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42e01f
a=rtpmap:109 rtx/90000
a=fmtp:109 apt=108
a=rtpmap:124 H264/90000
a=rtcp-fb:124 goog-remb
a=rtcp-fb:124 transport-cc
a=rtcp-fb:124 ccm fir
a=rtcp-fb:124 nack
a=rtcp-fb:124 nack pli
a=fmtp:124 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=4d0032
a=rtpmap:120 rtx/90000
a=fmtp:120 apt=124
a=rtpmap:123 H264/90000
a=rtcp-fb:123 goog-remb
a=rtcp-fb:123 transport-cc
a=rtcp-fb:123 ccm fir
a=rtcp-fb:123 nack
a=rtcp-fb:123 nack pli
a=fmtp:123 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=640032
a=rtpmap:119 rtx/90000
a=fmtp:119 apt=123
a=rtpmap:114 red/90000
a=rtpmap:115 rtx/90000
a=fmtp:115 apt=114
a=rtpmap:116 ulpfec/90000
a=ssrc-group:FID 3515883384 3276995665
a=ssrc:3515883384 cname:VIch5gFwZWnmeoRt
a=ssrc:3515883384 msid:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1 2dd8cc28-21f7-4fb7-8847-19da24730488
a=ssrc:3515883384 mslabel:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1
a=ssrc:3515883384 label:2dd8cc28-21f7-4fb7-8847-19da24730488
a=ssrc:3276995665 cname:VIch5gFwZWnmeoRt
a=ssrc:3276995665 msid:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1 2dd8cc28-21f7-4fb7-8847-19da24730488
a=ssrc:3276995665 mslabel:4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1
a=ssrc:3276995665 label:2dd8cc28-21f7-4fb7-8847-19da24730488

2020-04-26T05:03:41,875886 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb958038510>  Add format support, media: audio, codec: opus/48000/2
2020-04-26T05:03:41,875957 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb958038510>  Add format support, media: audio, codec: PCMU/8000
2020-04-26T05:03:41,875998 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb958038510>  Add format support, media: video, codec: VP8/90000
2020-04-26T05:03:41,876035 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb958038510>  Add format support, media: video, codec: H264/90000
2020-04-26T05:03:41,878312 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb95400cbb0>  Add format support, media: audio, codec: opus/48000/2
2020-04-26T05:03:41,878401 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb95400cbb0>  Add format support, media: audio, codec: PCMU/8000
2020-04-26T05:03:41,878447 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb95400cbb0>  Add format support, media: video, codec: VP8/90000
2020-04-26T05:03:41,878486 14068 0x00007fba06509700    info sdprtpavpmediahandler     kmssdprtpavpmediahandler.c:1249 kms_sdp_rtp_avp_media_handler_add_codec() <KmsSdpRtpSavpfMediaHandler@0x7fb95400cbb0>  Add format support, media: video, codec: H264/90000
2020-04-26T05:03:41,880009 14068 0x00007fba06509700    info kmssdpsession             kmssdpsession.c:140 kms_sdp_session_process_offer() <kmswebrtcsession21>  Generated SDP Answer:
v=0
o=- 3796837421 3796837421 IN IP4 0.0.0.0
s=Kurento Media Server
c=IN IP4 0.0.0.0
t=0 0
a=msid-semantic: WMS 4Wno1nVcFemXD5Y263c8jEdvDvnBEADxObx1
a=group:BUNDLE 0 1
m=audio 1 UDP/TLS/RTP/SAVPF 111 0
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=sendrecv
a=mid:0
a=rtcp:9 IN IP4 0.0.0.0
a=rtpmap:111 opus/48000/2
a=rtpmap:0 PCMU/8000
a=setup:active
a=rtcp-mux
a=fmtp:111 minptime=10;useinbandfec=1
a=ssrc:3688527842 cname:user3408205677@host-37582c8a
a=ice-ufrag:eD6E
a=ice-pwd:Q7x5jqzzaQDpFCi9mXI763
a=fingerprint:sha-256 9A:91:44:DB:B1:74:C4:AC:71:96:51:22:8E:E4:1B:D6:D3:F5:6B:F8:90:9C:83:F1:AF:AE:EC:C3:E8:C8:41:30
m=video 1 UDP/TLS/RTP/SAVPF 96 102 127 125 108 124 123
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=sendrecv
a=mid:1
a=rtcp:9 IN IP4 0.0.0.0
a=rtpmap:96 VP8/90000
a=rtpmap:102 H264/90000
a=rtpmap:127 H264/90000
a=rtpmap:125 H264/90000
a=rtpmap:108 H264/90000
a=rtpmap:124 H264/90000
a=rtpmap:123 H264/90000
a=rtcp-fb:96 goog-remb
a=rtcp-fb:96 ccm fir
a=rtcp-fb:96 nack
a=rtcp-fb:96 nack pli
a=rtcp-fb:102 goog-remb
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli
a=rtcp-fb:127 goog-remb
a=rtcp-fb:127 ccm fir
a=rtcp-fb:127 nack
a=rtcp-fb:127 nack pli
a=rtcp-fb:125 goog-remb
a=rtcp-fb:125 ccm fir
a=rtcp-fb:125 nack
a=rtcp-fb:125 nack pli
a=rtcp-fb:108 goog-remb
a=rtcp-fb:108 ccm fir
a=rtcp-fb:108 nack
a=rtcp-fb:108 nack pli
a=rtcp-fb:124 goog-remb
a=rtcp-fb:124 ccm fir
a=rtcp-fb:124 nack
a=rtcp-fb:124 nack pli
a=rtcp-fb:123 goog-remb
a=rtcp-fb:123 ccm fir
a=rtcp-fb:123 nack
a=rtcp-fb:123 nack pli
a=setup:active
a=rtcp-mux
a=fmtp:102 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42001f
a=fmtp:127 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42001f
a=fmtp:125 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f
a=fmtp:108 level-asymmetry-allowed=1;packetization-mode=0;profile-level-id=42e01f
a=fmtp:124 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=4d0032
a=fmtp:123 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=640032
a=ssrc:2019658114 cname:user3408205677@host-37582c8a
a=ice-ufrag:eD6E
a=ice-pwd:Q7x5jqzzaQDpFCi9mXI763
a=fingerprint:sha-256 9A:91:44:DB:B1:74:C4:AC:71:96:51:22:8E:E4:1B:D6:D3:F5:6B:F8:90:9C:83:F1:AF:AE:EC:C3:E8:C8:41:30

2020-04-26T05:03:41,880725 14068 0x00007fb9cf994700   fixme basesink                  gstbasesink.c:3125 gst_base_sink_default_event() <nicesink21>  stream-start event without group-id. Consider implementing group-id handling in the upstream elements
2020-04-26T05:03:41,881180 14068 0x00007fb9ce452700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <nicesrc21:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2020-04-26T05:03:41,882193 14068 0x00007fba06509700    info basertpendpoint           kmsbasertpendpoint.c:1118 kms_base_rtp_endpoint_start_transport_send() <kmswebrtcendpoint21>  Media 'video' has REMB
2020-04-26T05:03:41,882273 14068 0x00007fba06509700    info basertpendpoint           kmsbasertpendpoint.c:1064 kms_base_rtp_endpoint_create_remb_manager() <kmswebrtcendpoint21>  Creating REMB for session ID 0 (kmswebrtcendpoint21-sess0) and remote video SSRC 3515883384
2020-04-26T05:03:41,882327 14068 0x00007fba06509700    info basertpendpoint           kmsbasertpendpoint.c:1075 kms_base_rtp_endpoint_create_remb_manager() <kmswebrtcendpoint21>  REMB: Set RTCP min interval to 500 ms
2020-04-26T05:03:41,882441 14068 0x00007fba06509700    info kmswebrtcsession          kmswebrtcsession.c:1575 kms_webrtc_session_start_transport_send() <kmswebrtcsession21>  Started transport for media: audio, index: 0
2020-04-26T05:03:41,882513 14068 0x00007fba06509700    info kmswebrtcsession          kmswebrtcsession.c:1575 kms_webrtc_session_start_transport_send() <kmswebrtcsession21>  Started transport for media: video, index: 1
2020-04-26T05:03:41,917040 14068 0x00007fba0950f700    info webrtcendpoint            kmswebrtcendpoint.c:427 kms_webrtc_endpoint_gather_candidates() <kmswebrtcendpoint21>  Gather candidates for session 'kmswebrtcendpoint21-sess0'
2020-04-26T05:03:41,917143 14068 0x00007fba0950f700    info kmswebrtcsession          kmswebrtcsession.c:819 kms_webrtc_session_gather_candidates() <kmswebrtcsession21>  Gather candidates
2020-04-26T05:03:41,917233 14068 0x00007fba0950f700    info kmswebrtcbaseconnection   kmswebrtcbaseconnection.c:229 kms_webrtc_base_connection_agent_add_net_addr() <NiceAgent@0x7fb9f00822a0>  Added local address: 172.16.1.10
2020-04-26T05:03:41,970727 14068 0x00007fba06d0a700    info webrtcendpoint            kmswebrtcendpoint.c:451 kms_webrtc_endpoint_add_ice_candidate() <kmswebrtcendpoint21>  Add remote candidate 'candidate:3259969598 1 udp 41885439 60.16.7.147 50031 typ relay raddr 0.0.0.0 rport 0 generation 0 ufrag CNY+ network-id 1 network-cost 10' for session 'kmswebrtcendpoint21-sess0'
2020-04-26T05:03:42,005936 14068 0x00007fb9ce452700    info kmsiceniceagent           kmsiceniceagent.c:228 kms_ice_nice_agent_new_selected_pair_full() <KmsIceNiceAgent@0x7fb9b00a5260>  [NewCandidatePairSelected] local: 'candidate:4 1 UDP 1677722111 60.16.7.147 28261 typ srflx raddr 172.16.1.10 rport 28261', remote: 'candidate:remote1 1 UDP 1853824767 172.16.1.10 50031 typ prflx', stream_id: 1, component_id: 1
2020-04-26T05:03:42,006040 14068 0x00007fb9ce452700    info webrtcendpoint            kmswebrtcendpoint.c:284 new_selected_pair_full() <kmswebrtcendpoint21>  New candidate pair selected, local: 'candidate:4 1 UDP 1677722111 60.16.7.147 28261 typ srflx raddr 172.16.1.10 rport 28261', remote: 'candidate:remote1 1 UDP 1853824767 172.16.1.10 50031 typ prflx', stream_id: '1', component_id: 1
2020-04-26T05:03:42,941476 14068 0x00007fb9ce452700    info kmsutils                  kmsutils.c:494 kms_utils_pad_monitor_gaps() <'':sink_video_default>  Add probe: Detect stream gaps
2020-04-26T05:03:42,958810 14068 0x00007fb9ce452700    info basertpendpoint           kmsbasertpendpoint.c:1914 kms_base_rtp_endpoint_jitterbuffer_set_latency() <rtpjitterbuffer29>  Add probe: Set jitterbuffer latency
2020-04-26T05:03:42,958894 14068 0x00007fb9ce452700    info basertpendpoint           kmsbasertpendpoint.c:1963 kms_base_rtp_endpoint_jitterbuffer_monitor_rtp_out() <rtpjitterbuffer29>  Add probe: Adjust jitterbuffer PTS out
2020-04-26T05:03:42,959314 14068 0x00007fb9ce452700    info basertpendpoint           kmsbasertpendpoint.c:2008 kms_base_rtp_endpoint_jitterbuffer_monitor_rtcp_in() <rtpjitterbuffer29>  Add probe: Get jitterbuffer RTCP SR timing
2020-04-26T05:03:42,959573 14068 0x00007fb9b5d7c700    info basertpendpoint           kmsbasertpendpoint.c:1899 kms_base_rtp_endpoint_jitterbuffer_set_latency_probe() <rtpjitterbuffer29>  Setting latency to: 500
2020-04-26T05:03:42,959700 14068 0x00007fb9b5d7c700    info basertpendpoint           kmsbasertpendpoint.c:1902 kms_base_rtp_endpoint_jitterbuffer_set_latency_probe() <rtpjitterbuffer29>  Jitterbuffer latency set; remove probe
2020-04-26T05:03:42,960069 14068 0x00007fb9b5d7c700    info kmsutils                  kmsutils.c:494 kms_utils_pad_monitor_gaps() <'':sink>  Add probe: Detect stream gaps
2020-04-26T05:03:42,960912 14068 0x00007fb9b5d7c700    info kmsutils                  kmsutils.c:1481 kms_utils_depayloader_monitor_pts_out() <rtpvp8depay11>  Add probe: Adjust depayloader PTS out
2020-04-26T05:03:42,982722 14068 0x00007fb9ce452700    info basertpendpoint           kmsbasertpendpoint.c:1914 kms_base_rtp_endpoint_jitterbuffer_set_latency() <rtpjitterbuffer30>  Add probe: Set jitterbuffer latency
2020-04-26T05:03:42,982805 14068 0x00007fb9ce452700    info basertpendpoint           kmsbasertpendpoint.c:1963 kms_base_rtp_endpoint_jitterbuffer_monitor_rtp_out() <rtpjitterbuffer30>  Add probe: Adjust jitterbuffer PTS out
2020-04-26T05:03:42,983171 14068 0x00007fb9ce452700    info basertpendpoint           kmsbasertpendpoint.c:2008 kms_base_rtp_endpoint_jitterbuffer_monitor_rtcp_in() <rtpjitterbuffer30>  Add probe: Get jitterbuffer RTCP SR timing
2020-04-26T05:03:42,983377 14068 0x00007fb997fff700    info basertpendpoint           kmsbasertpendpoint.c:1899 kms_base_rtp_endpoint_jitterbuffer_set_latency_probe() <rtpjitterbuffer30>  Setting latency to: 100
2020-04-26T05:03:42,983504 14068 0x00007fb997fff700    info basertpendpoint           kmsbasertpendpoint.c:1902 kms_base_rtp_endpoint_jitterbuffer_set_latency_probe() <rtpjitterbuffer30>  Jitterbuffer latency set; remove probe
2020-04-26T05:03:42,983610 14068 0x00007fb9b5d7c700    info agnosticbin               kmsagnosticbin.c:899 input_bin_src_caps_probe() <kmsagnosticbin2-37>  Set input caps: video/x-vp8, framerate=(fraction)29/1, height=(int)480, width=(int)640, profile=(string)0
2020-04-26T05:03:42,983724 14068 0x00007fb9b5d7c700    info agnosticbin               kmsagnosticbin.c:774 kms_agnostic_bin2_link_pad() <kmsagnosticbin2-37>  Upstream provided caps: ANY
2020-04-26T05:03:42,983869 14068 0x00007fb997fff700    info kmsutils                  kmsutils.c:494 kms_utils_pad_monitor_gaps() <'':sink>  Add probe: Detect stream gaps
2020-04-26T05:03:42,984073 14068 0x00007fb9b5d7c700    info agnosticbin               kmsagnosticbin.c:783 kms_agnostic_bin2_link_pad() <kmsagnosticbin2-37>  Downstream wanted caps: video/x-raw; video/x-dirac; image/png; image/jpeg; video/x-smoke; video/x-asus, asusversion=(int)1; video/x-asus, asusversion=(int)2; image/bmp; video/x-dnxhd; video/x-dv; video/x-ffv, ffvversion=(int)1; video/x-gst_ff-ffvhuff; video/x-flash-screen; video/x-flash-video, flvversion=(int)1; video/x-h261; video/x-h263, variant=(string)itu, h263version=(string)h263; video/x-h263, variant=(string)itu, h263version=(string)h263p; video/x-huffyuv; video/mpeg, mpegversion=(int)1; video/mpeg, mpegversion=(int)2; video/mpeg, mpegversion=(int)4; video/x-msmpeg, msmpegversion=(int)41; video/x-msmpeg, msmpegversion=(int)42; video/x-msmpeg, msmpegversion=(int)43; video/x-gst_ff-pam; image/pbm; video/x-gst_ff-pgm; video/x-gst_ff-pgmyuv; image/ppm; video/x-rle, layout=(string)quicktime; video/x-gst_ff-roqvideo; video/x-pn-realvideo, rmversion=(int)1; video/x-pn-realvideo, rmversion=(int)2; video/x-gst_ff-snow; video/x-svq, svqversion=(int)1; video/x-wmv, wmvversion=(int)1; video/x-wmv, wmvversion=(int)2; video/x-gst_ff-zmbv; video/x-theora; video/x-h264; video/x-gst_ff-libxvid; video/x-xvid; video/mpeg, mpegversion=(int)[ 1, 2 ]; video/x-vp8; application/x-yuv4mpeg, y4mversion=(int)2
2020-04-26T05:03:42,984259 14068 0x00007fb9b5d7c700    info agnosticbin               kmsagnosticbin.c:743 kms_agnostic_bin2_find_or_create_bin_for_caps() <kmsagnosticbin2-37>  TRANSCODING INACTIVE for video
2020-04-26T05:03:42,984600 14068 0x00007fb997fff700    info kmsutils                  kmsutils.c:1481 kms_utils_depayloader_monitor_pts_out() <rtpopusdepay12>  Add probe: Adjust depayloader PTS out
2020-04-26T05:03:42,986038 14068 0x00007fb997fff700    info agnosticbin               kmsagnosticbin.c:899 input_bin_src_caps_probe() <kmsagnosticbin2-38>  Set input caps: audio/x-opus, rate=(int)48000, channels=(int)2, channel-mapping-family=(int)0, stream-count=(int)1, coupled-count=(int)1, streamheader=(buffer)< 4f707573486561640102000080bb0000000000, 4f707573546167731f0000004753747265616d657220656e636f64656420766f72626973636f6d6d656e740000000001 >
2020-04-26T05:03:42,986166 14068 0x00007fb997fff700    info agnosticbin               kmsagnosticbin.c:774 kms_agnostic_bin2_link_pad() <kmsagnosticbin2-38>  Upstream provided caps: ANY
2020-04-26T05:03:42,986400 14068 0x00007fb997fff700    info agnosticbin               kmsagnosticbin.c:783 kms_agnostic_bin2_link_pad() <kmsagnosticbin2-38>  Downstream wanted caps: audio/x-raw; audio/x-sbc; audio/x-mulaw; audio/x-flac; audio/x-alaw; audio/x-speex; audio/x-ac3; audio/x-alac; audio/mpeg, mpegversion=(int)1, layer=(int)2; audio/x-nellymoser; audio/x-gst_ff-sonic; audio/x-gst_ff-sonicls; audio/x-wma, wmaversion=(int)1; audio/x-wma, wmaversion=(int)2; audio/x-dpcm, layout=(string)roq; audio/x-adpcm, layout=(string)adx; audio/x-adpcm, layout=(string)g726; audio/x-adpcm, layout=(string)quicktime; audio/x-adpcm, layout=(string)dvi; audio/x-adpcm, layout=(string)microsoft; audio/x-adpcm, layout=(string)swf; audio/x-adpcm, layout=(string)yamaha; audio/mpeg, mpegversion=(int)4; audio/mpeg, mpegversion=(int)1, layer=(int)3; audio/x-celt; audio/mpeg, mpegversion=(int)[ 2, 4 ]; audio/x-vorbis; audio/x-opus; audio/AMR, rate=(int)[ 8000, 16000 ], channels=(int)1; audio/x-gsm
2020-04-26T05:03:42,986509 14068 0x00007fb997fff700    info agnosticbin               kmsagnosticbin.c:743 kms_agnostic_bin2_find_or_create_bin_for_caps() <kmsagnosticbin2-38>  TRANSCODING INACTIVE for audio
2020-04-26T05:03:42,988779 14068 0x00007fb996bb1700    info agnosticbin               kmsagnosticbin.c:899 input_bin_src_caps_probe() <kmsagnosticbin2-35>  Set input caps: audio/x-opus, rate=(int)48000, channels=(int)2, channel-mapping-family=(int)0, stream-count=(int)1, coupled-count=(int)1, streamheader=(buffer)< 4f707573486561640102000080bb0000000000, 4f707573546167731f0000004753747265616d657220656e636f64656420766f72626973636f6d6d656e740000000001 >
2020-04-26T05:03:43,152929 14068 0x00007fb9977fe700    info agnosticbin               kmsagnosticbin.c:899 input_bin_src_caps_probe() <kmsagnosticbin2-36>  Set input caps: video/x-vp8, framerate=(fraction)29/1, height=(int)480, width=(int)640, profile=(string)0
2020-04-26T05:03:45,454874 14068 0x00007fba05d08700    info KurentoServerMethods      ServerMethods.cpp:814 ping()  WebSocket Ping/Pong with sessionId 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:03:48,466875 14068 0x00007fba0d517700   debug KurentoMediaSet           MediaSet.cpp:470 async_delete()  Destroying WebRtcEndpoint -> eb483baf-6394-45a5-afc6-52a68c8b37cd_kurento.MediaPipeline/b1818cf5-48da-4159-8aba-8e577ab3c49d_kurento.WebRtcEndpoint
2020-04-26T05:03:48,516555 14068 0x00007fba0fd1c700   debug KurentoMediaSet           MediaSet.cpp:470 async_delete()  Destroying PassThrough -> eb483baf-6394-45a5-afc6-52a68c8b37cd_kurento.MediaPipeline/8ae359dc-f181-4780-b59b-a5c74c6cd2da_kurento.PassThrough
2020-04-26T05:03:48,517650 14068 0x00007fba0d517700   debug KurentoMediaSet           MediaSet.cpp:470 async_delete()  Destroying MediaPipeline -> eb483baf-6394-45a5-afc6-52a68c8b37cd_kurento.MediaPipeline
2020-04-26T05:04:28,303718 14068 0x00007fba05507700    info KurentoWebSocketTransport WebSocketTransport.cpp:296 keepAliveSessions()  Keep alive 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:05:28,303950 14068 0x00007fba05507700    info KurentoWebSocketTransport WebSocketTransport.cpp:296 keepAliveSessions()  Keep alive 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:06:28,304188 14068 0x00007fba05507700    info KurentoWebSocketTransport WebSocketTransport.cpp:296 keepAliveSessions()  Keep alive 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:07:28,132685 14068 0x00007fba0ad12700   debug KurentoMediaSet           MediaSet.cpp:123 doGarbageCollection()  Running garbage collector
2020-04-26T05:07:28,304411 14068 0x00007fba05507700    info KurentoWebSocketTransport WebSocketTransport.cpp:296 keepAliveSessions()  Keep alive 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:07:45,454890 14068 0x00007fba08d0e700    info KurentoServerMethods      ServerMethods.cpp:814 ping()  WebSocket Ping/Pong with sessionId 50f700b0-73c8-4a07-831c-e3b67f0ed8ec
2020-04-26T05:08:28,304609 14068 0x00007fba05507700    info KurentoWebSocketTransport WebSocketTransport.cpp:296 keepAliveSessions()  Keep alive 50f700b0-73c8-4a07-831c-e3b67f0ed8ec

ss output:

root@ychz-PowerEdge-R730:~# date
2020年 04月 26日 星期日 05:12:45 CST
root@ychz-PowerEdge-R730:~# ss -nplut | grep 28261
udp   UNCONN  768     0                172.16.1.10:28261          0.0.0.0:*      users:(("kurento-media-s",pid=14068,fd=195))

@j1elo
Copy link
Member

j1elo commented Apr 26, 2020

We've been doing some analysis and here: #460

@j1elo
Copy link
Member

j1elo commented Apr 26, 2020

Duplicate of #460

@j1elo j1elo marked this as a duplicate of #460 Apr 26, 2020
@j1elo j1elo closed this as completed Apr 26, 2020
@ifplusor
Copy link

We've been doing some analysis and here: #460

Thank you.

j1elo added a commit to Kurento/kms-elements that referenced this issue Apr 28, 2020
nice_agent_remove_stream(), called from
kms_ice_nice_agent_remove_stream(), was silently converted from
synchronous to asynchronous in libnice 0.1.16. I know that Semantic
Versioning tells us that 0.X.Y should be considered as unstable API, but
come on, that change wasn't *nice* of libnice ;-)

To solve the issue, we need to run a last iteration of its GMainLoop
context in order to allow it release all resources and object
references. Otherwise, libnice takes a reference to the NiceAgent object
in nice_agent_remove_stream(), and it never gets to release it, because
the unref is done in the callback function on_stream_refreshes_pruned().

Thanks to @omgold for finding the root cause of the issue and proposing
a solution!
Kurento/bugtracker#460 (comment)

A bug report has been filled in libnice as a result of this commit:
https://gitlab.freedesktop.org/libnice/libnice/issues/110

Fixes Kurento/bugtracker#253
Fixes Kurento/bugtracker#460
rolfbsts pushed a commit to ESTOS/kms-elements that referenced this issue Dec 7, 2020
nice_agent_remove_stream(), called from
kms_ice_nice_agent_remove_stream(), was silently converted from
synchronous to asynchronous in libnice 0.1.16. I know that Semantic
Versioning tells us that 0.X.Y should be considered as unstable API, but
come on, that change wasn't *nice* of libnice ;-)

To solve the issue, we need to run a last iteration of its GMainLoop
context in order to allow it release all resources and object
references. Otherwise, libnice takes a reference to the NiceAgent object
in nice_agent_remove_stream(), and it never gets to release it, because
the unref is done in the callback function on_stream_refreshes_pruned().

Thanks to @omgold for finding the root cause of the issue and proposing
a solution!
Kurento/bugtracker#460 (comment)

A bug report has been filled in libnice as a result of this commit:
https://gitlab.freedesktop.org/libnice/libnice/issues/110

Fixes Kurento/bugtracker#253
Fixes Kurento/bugtracker#460
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants